Volteer: suspend/resume: Max98373 falls off the bus on resume and doesn't reattach.

[plbossart]

Low-level hardware error seen in unrelated nocodec test.

https://sof-ci.sh.intel.com/#/result/planresultdetail/5452?model=TGLU_VOLT_SDW&testcase=check-suspend-resume-with-capture-5

Recipe:
Start Time: 2021-07-23 01:00:47 UTC
End Time: 2021-07-23 04:34:04 UTC
Kernel Branch: topic/sof-dev
Kernel Commit: d54b780
SOF Branch: main
SOF Commit: 52bc39f

Hardware: jf-tglu-volt-sdw-01

LINK0 RESUME
[ 7159.394865] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: powering up all links
[ 7159.394870] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: first link up, programming SYNCPRD
[ 7159.395915] kernel: rt5682 sdw:0:025d:5682:00: sdw_modify_slave_status: initializing enumeration and init completion for Slave 1
[ 7159.397149] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x2
[ 7159.397159] kernel: soundwire sdw-master-0: Slave attached, programming device number
[ 7159.397494] kernel: soundwire sdw-master-0: SDW Slave Addr: 20025d568200
[ 7159.397495] kernel: soundwire sdw-master-0: SDW Slave class_id 0x00, mfg_id 0x025d, part_id 0x5682, unique_id 0x0, version 0x2
[ 7159.397498] kernel: soundwire sdw-master-0: Slave already registered, reusing dev_num:1
[ 7159.397811] kernel: soundwire_intel soundwire_intel.link.0: Msg ignored for Slave 0
[ 7159.397813] kernel: soundwire sdw-master-0: No more devices to enumerate
[ 7159.397850] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x21
[ 7159.397854] kernel: rt5682 sdw:0:025d:5682:00: sdw_modify_slave_status: signaling enumeration completion for Slave 1
[ 7159.397964] kernel: rt5682 sdw:0:025d:5682:00: Bus clash detected before INT mask is enabled
[ 7159.720037] kernel: rt5682 sdw:0:025d:5682:00: rt5682_io_init hw_init complete: 0
[ 7159.720042] kernel: rt5682 sdw:0:025d:5682:00: sdw_handle_slave_status: signaling initialization completion for Slave 1

LINK1 RESUME
[ 7159.720964] kernel: max98373 sdw:1:019f:8373:00:7: sdw_modify_slave_status: initializing enumeration and init completion for Slave 1
[ 7159.720976] kernel: max98373 sdw:1:019f:8373:00:3: sdw_modify_slave_status: initializing enumeration and init completion for Slave 2
[ 7159.722229] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x2
[ 7159.722239] kernel: soundwire sdw-master-1: Slave attached, programming device number
[ 7159.722551] kernel: soundwire sdw-master-1: SDW Slave Addr: 27019f837300
[ 7159.722552] kernel: soundwire sdw-master-1: SDW Slave class_id 0x00, mfg_id 0x019f, part_id 0x8373, unique_id 0x7, version 0x2
[ 7159.722555] kernel: soundwire sdw-master-1: Slave already registered, reusing dev_num:1
[ 7159.722866] kernel: soundwire_intel soundwire_intel.link.1: Msg ignored for Slave 0
[ 7159.722867] kernel: soundwire sdw-master-1: No more devices to enumerate
[ 7159.722901] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x21
[ 7159.722905] kernel: max98373 sdw:1:019f:8373:00:7: sdw_modify_slave_status: signaling enumeration completion for Slave 1
[ 7159.735160] kernel: max98373 sdw:1:019f:8373:00:7: Reset completed (retry:0)
[ 7159.737899] kernel: max98373 sdw:1:019f:8373:00:7: sdw_handle_slave_status: signaling initialization completion for Slave 1

LINK1 Device1 resumed

[ 7159.743729] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x2
[ 7159.743739] kernel: max98373 sdw:1:019f:8373:00:7: sdw_modify_slave_status: initializing enumeration and init completion for Slave 1

LINK1 Device1 not longer ATTACHED!!

[ 7159.743749] kernel: soundwire sdw-master-1: Slave attached, programming device number
[ 7159.743986] kernel: soundwire sdw-master-1: SDW Slave Addr: 23019f837300
[ 7159.743989] kernel: soundwire sdw-master-1: SDW Slave class_id 0x00, mfg_id 0x019f, part_id 0x8373, unique_id 0x3, version 0x2
[ 7159.743993] kernel: soundwire sdw-master-1: Slave already registered, reusing dev_num:2
[ 7159.744343] kernel: soundwire_intel soundwire_intel.link.1: Msg ignored for Slave 0
[ 7159.744346] kernel: soundwire sdw-master-1: No more devices to enumerate

LINK1 All devices enumerated

[ 7159.744525] kernel: soundwire_intel soundwire_intel.link.1: Slave status change: 0x201

LINK DEVICE2 shown as having completed its enumeration

[ 7159.744532] kernel: max98373 sdw:1:019f:8373:00:3: sdw_modify_slave_status: signaling enumeration completion for Slave 2
[ 7159.756896] kernel: max98373 sdw:1:019f:8373:00:3: Reset completed (retry:0)
[ 7159.759562] kernel: max98373 sdw:1:019f:8373:00:3: sdw_handle_slave_status: signaling initialization completion for Slave 2

LINK1 Device2 resumed

[ 7159.892336] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 7159.892496] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 7160.392278] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 7160.392323] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 7162.041548] kernel: ax88179_178a 4-1:1.0 enx000ec66a790d: ax88179 - Link status is: 1
[ 7164.955865] kernel: max98373 sdw:1:019f:8373:00:7: Initialization not complete, timed out
[ 7164.955872] kernel: PM: dpm_run_callback(): acpi_subsys_resume+0x0/0x70 returns -110
[ 7164.955886] kernel: max98373 sdw:1:019f:8373:00:7: PM: failed to resume: error -110

LINK1 Device never showed up again

dmesg.txt

@bardliao @RanderWang @ryans-lee FYI

[mengdonglin]

It may be related to

• [BUG][MAX98373][SDW] "Initialization not complete, timed out" in suspend-resume test #2522

[plbossart]

That's quite possible indeed @mengdonglin. I added the log from the Intel test 592 dmesg.txt

kernel: [   37.392542] intel-sdw intel-sdw.0: intel_link_power_up: powering up all links
kernel: [   37.392542] intel-sdw intel-sdw.0: intel_link_power_up: first link up, programming SYNCPRD
kernel: [   37.393184] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [   37.393185] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [   37.415851] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.415858] soundwire sdw-master-1: Slave attached, programming device number
kernel: [   37.416018] soundwire sdw-master-1: SDW Slave Addr: 27019f837300
kernel: [   37.416020] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 7, version 2
kernel: [   37.416021] soundwire sdw-master-1: Slave already registered, reusing dev_num:1
kernel: [   37.416354] soundwire sdw-master-1: SDW Slave Addr: 23019f837300
kernel: [   37.416357] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 3, version 2
kernel: [   37.416358] soundwire sdw-master-1: Slave already registered, reusing dev_num:2
kernel: [   37.416576] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416578] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416578] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416579] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416580] intel-sdw intel-sdw.1: Msg ignored for Slave 0
kernel: [   37.416582] soundwire sdw-master-1: No more devices to enumerate
kernel: [   37.416604] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.416610] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [   37.416744] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
kernel: [   37.416889] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.416893] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2

that means Device 1 (unique number 7) is no longer attached

kernel: [   37.417032] max98373 sdw:1:19f:8373:0:7: Bus clash detected

That would be problematic, if the device is indeed no longer attached/enumerated, it CANNOT generate interrupts.

When an interrupt is received we should double-check if the device is actually attached.

[bardliao]

That's quite possible indeed @mengdonglin. I added the log from the Intel test 592 dmesg.txt

kernel: [   37.392542] intel-sdw intel-sdw.0: intel_link_power_up: powering up all links
kernel: [   37.392542] intel-sdw intel-sdw.0: intel_link_power_up: first link up, programming SYNCPRD
kernel: [   37.393184] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [   37.393185] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [   37.415851] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.415858] soundwire sdw-master-1: Slave attached, programming device number
kernel: [   37.416018] soundwire sdw-master-1: SDW Slave Addr: 27019f837300
kernel: [   37.416020] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 7, version 2
kernel: [   37.416021] soundwire sdw-master-1: Slave already registered, reusing dev_num:1
kernel: [   37.416354] soundwire sdw-master-1: SDW Slave Addr: 23019f837300
kernel: [   37.416357] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 3, version 2
kernel: [   37.416358] soundwire sdw-master-1: Slave already registered, reusing dev_num:2
kernel: [   37.416576] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416578] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416578] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416579] intel-sdw intel-sdw.1: Msg Ack not received
kernel: [   37.416580] intel-sdw intel-sdw.1: Msg ignored for Slave 0
kernel: [   37.416582] soundwire sdw-master-1: No more devices to enumerate
kernel: [   37.416604] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.416610] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [   37.416744] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
kernel: [   37.416889] intel-sdw intel-sdw.1: Slave status change
kernel: [   37.416893] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2

that means Device 1 (unique number 7) is no longer attached

Sorry @plbossart I am confused here. Why max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2 means device 1 (unique number 7) is no longer attached? Doesn't it mean device 2 (unique number 3) is no longer attached?

kernel: [ 37.417032] max98373 sdw:1:19f:8373:0:7: Bus clash detected

That would be problematic, if the device is indeed no longer attached/enumerated, it CANNOT generate interrupts.

When an interrupt is received we should double-check if the device is actually attached.

[plbossart]

kernel: [ 37.416610] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 37.416744] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
kernel: [ 37.416889] intel-sdw intel-sdw.1: Slave status change
kernel: [ 37.416893] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2

that means Device 1 (unique number 7) is no longer attached

Sorry @plbossart I am confused here. Why max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2 means device 1 (unique number 7) is no longer attached? Doesn't it mean device 2 (unique number 3) is no longer attached?

Yes indeed, my mistake @bardliao

[plbossart]

This error was seen on TGL RVP with 2 Max98373 devices

https://sof-ci.sh.intel.com/#/result/planresultdetail/5652?model=TGLU_RVP_SDW&testcase=check-suspend-resume-50

[ 7338.186858] kernel: rt1308 sdw:1:025d:1308:00:2: sdw_modify_slave_status: initializing enumeration and init completion for Slave 1
[ 7338.186864] kernel: rt1308 sdw:1:025d:1308:00:0: sdw_modify_slave_status: initializing enumeration and init completion for Slave 2
[ 7338.187730] kernel: soundwire sdw-master-1: Slave attached, programming device number
[ 7338.187898] kernel: soundwire sdw-master-1: SDW Slave Addr: 20025d130800
[ 7338.187899] kernel: soundwire sdw-master-1: SDW Slave class_id 0x00, mfg_id 0x025d, part_id 0x1308, unique_id 0x0, version 0x2
[ 7338.187901] kernel: soundwire sdw-master-1: Slave already registered, reusing dev_num:2
[ 7338.188140] kernel: soundwire_intel soundwire_intel.link.1: Msg ignored for Slave 0
[ 7338.188141] kernel: soundwire sdw-master-1: No more devices to enumerate
[ 7338.188184] kernel: rt1308 sdw:1:025d:1308:00:0: sdw_modify_slave_status: signaling enumeration completion for Slave 2
[ 7338.188247] kernel: rt1308 sdw:1:025d:1308:00:0: Bus clash detected before INT mask is enabled
[ 7338.318891] kernel: rt1308 sdw:1:025d:1308:00:0: rt1308_io_init m_btl_l=0x0, m_btl_r=0x0
[ 7338.318900] kernel: rt1308 sdw:1:025d:1308:00:0: rt1308_io_init c_btl_l=0x0, c_btl_r=0x0
[ 7338.326645] kernel: rt1308 sdw:1:025d:1308:00:0: rt1308_io_init hw_init complete
[ 7338.326649] kernel: rt1308 sdw:1:025d:1308:00:0: sdw_handle_slave_status: signaling initialization completion for Slave 2
[ 7338.326725] kernel: rt1308 sdw:1:025d:1308:00:0: sdw_modify_slave_status: initializing enumeration and init completion for Slave 2
[ 7338.326735] kernel: soundwire sdw-master-1: Slave attached, programming device number
[ 7338.326935] kernel: soundwire sdw-master-1: SDW Slave Addr: 22025d130800
[ 7338.326939] kernel: soundwire sdw-master-1: SDW Slave class_id 0x00, mfg_id 0x025d, part_id 0x1308, unique_id 0x2, version 0x2
[ 7338.326943] kernel: soundwire sdw-master-1: Slave already registered, reusing dev_num:1
[ 7338.327223] kernel: soundwire_intel soundwire_intel.link.1: Msg ignored for Slave 0
[ 7338.327227] kernel: soundwire sdw-master-1: No more devices to enumerate
[ 7338.327265] kernel: rt1308 sdw:1:025d:1308:00:2: sdw_modify_slave_status: signaling enumeration completion for Slave 1
[ 7338.327372] kernel: rt1308 sdw:1:025d:1308:00:2: Bus clash detected before INT mask is enabled
[ 7338.421021] kernel: rt711 sdw:0:025d:0711:00: Slave impl defined interrupt
[ 7338.421028] kernel: rt711 sdw:0:025d:0711:00: rt711_interrupt_callback control_port_stat=4
[ 7338.462795] kernel: rt1308 sdw:1:025d:1308:00:2: rt1308_io_init m_btl_l=0x4, m_btl_r=0x1b
[ 7338.462802] kernel: rt1308 sdw:1:025d:1308:00:2: rt1308_io_init c_btl_l=0x17a, c_btl_r=0xd7
[ 7338.470398] kernel: rt1308 sdw:1:025d:1308:00:2: rt1308_io_init hw_init complete
[ 7338.470402] kernel: rt1308 sdw:1:025d:1308:00:2: sdw_handle_slave_status: signaling initialization completion for Slave 1
[ 7343.613767] kernel: rt1308 sdw:1:025d:1308:00:0: Initialization not complete, timed out
[ 7343.613776] kernel: PM: dpm_run_callback(): acpi_subsys_resume+0x0/0x70 returns -110
[ 7343.613790] kernel: rt1308 sdw:1:025d:1308:00:0: PM: failed to resume: error -110

dmesg.txt

@bardliao @RanderWang is this something you've seen before on TGL RVP?

[bardliao]

@bardliao @RanderWang is this something you've seen before on TGL RVP?

IIRC, it is my first time to see this issue on RT1308. We saw -61 before, but it seems to be the first time to see timed out.

[RanderWang]

this is also my first time to see such issue on 1308

[plbossart]

Also seen on August 17 https://sof-ci.sh.intel.com/#/result/planresultdetail/5922

Also seen on today's daily test 7896.