ESP32 Hosted NG sometimes hangs on unload

[icvidal]

Checklist

• Checked the issue tracker for similar issues to ensure this is not a duplicate
• Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
• Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

rarely

Expected behavior

On rmmod esp_spi the module should cleanly unload in a short time.

Actual behavior (suspected bug)

Sometimes, rmmod hangs while running flush_workqueue as part of spi_exit.
The kernel prints messages like the following:

Aug  1 22:07:52 gadget user.err kernel: [134174.742830] INFO: task rmmod:12470 blocked for more than 122 seconds.

Some extra debug statements point to flushing spi_workqueue

Error logs or terminal output

/sys/kernel/config/usb_gadget # dmesg
[134297.617143]       Not tainted 5.10.21 #1
[134297.617150] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134297.617157] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134297.617175] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134297.617213]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134297.617250]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134297.617298]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134297.617345]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134297.617379]         ...
[134297.617391] Call Trace:
[134297.617410] [<80b04130>] __schedule+0x438/0xbbc
[134297.617424] [<80b0493c>] schedule+0x88/0x13c
[134297.617437] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134297.617449] [<80b06038>] wait_for_completion+0xa4/0x11c
[134297.617461] [<8006307c>] flush_workqueue+0x124/0x5a4
[134297.617483] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134297.617502] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134297.617520] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134297.617539] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134297.617552] [<8002d138>] syscall_common+0x34/0x58
[134297.617562] 
[134420.491385] INFO: task rmmod:12470 blocked for more than 368 seconds.
[134420.491402]       Not tainted 5.10.21 #1
[134420.491407] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134420.491414] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134420.491429] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134420.491462]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134420.491515]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134420.491553]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134420.491586]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134420.491617]         ...
[134420.491629] Call Trace:
[134420.491646] [<80b04130>] __schedule+0x438/0xbbc
[134420.491658] [<80b0493c>] schedule+0x88/0x13c
[134420.491668] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134420.491679] [<80b06038>] wait_for_completion+0xa4/0x11c
[134420.491690] [<8006307c>] flush_workqueue+0x124/0x5a4
[134420.491711] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134420.491728] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134420.491745] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134420.491760] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134420.491771] [<8002d138>] syscall_common+0x34/0x58
[134420.491780] 
[134543.365662] INFO: task rmmod:12470 blocked for more than 491 seconds.
[134543.365678]       Not tainted 5.10.21 #1
[134543.365685] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134543.365694] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134543.365712] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134543.365756]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134543.365803]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134543.365846]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134543.365883]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134543.365918]         ...
[134543.365931] Call Trace:
[134543.365950] [<80b04130>] __schedule+0x438/0xbbc
[134543.365963] [<80b0493c>] schedule+0x88/0x13c
[134543.365975] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134543.365985] [<80b06038>] wait_for_completion+0xa4/0x11c
[134543.365997] [<8006307c>] flush_workqueue+0x124/0x5a4
[134543.366016] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134543.366035] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134543.366051] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134543.366067] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134543.366078] [<8002d138>] syscall_common+0x34/0x58
[134543.366086] 
[134666.239941] INFO: task rmmod:12470 blocked for more than 614 seconds.
[134666.239958]       Not tainted 5.10.21 #1
[134666.239964] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134666.239974] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134666.239991] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134666.240033]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134666.240071]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134666.240110]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134666.240150]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134666.240185]         ...
[134666.240197] Call Trace:
[134666.240214] [<80b04130>] __schedule+0x438/0xbbc
[134666.240227] [<80b0493c>] schedule+0x88/0x13c
[134666.240240] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134666.240250] [<80b06038>] wait_for_completion+0xa4/0x11c
[134666.240260] [<8006307c>] flush_workqueue+0x124/0x5a4
[134666.240281] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134666.240298] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134666.240313] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134666.240329] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134666.240340] [<8002d138>] syscall_common+0x34/0x58
[134666.240348] 
[134789.114236] INFO: task rmmod:12470 blocked for more than 737 seconds.
[134789.114253]       Not tainted 5.10.21 #1
[134789.114260] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134789.114267] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134789.114282] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134789.114322]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134789.114362]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134789.114396]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134789.114425]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134789.114454]         ...
[134789.114464] Call Trace:
[134789.114482] [<80b04130>] __schedule+0x438/0xbbc
[134789.114494] [<80b0493c>] schedule+0x88/0x13c
[134789.114506] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134789.114516] [<80b06038>] wait_for_completion+0xa4/0x11c
[134789.114529] [<8006307c>] flush_workqueue+0x124/0x5a4
[134789.114555] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134789.114576] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134789.114596] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134789.117307] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134789.117325] [<8002d138>] syscall_common+0x34/0x58
[134789.117338] 
[134911.988489] INFO: task rmmod:12470 blocked for more than 860 seconds.
[134911.988504]       Not tainted 5.10.21 #1
[134911.988509] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[134911.988515] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[134911.988529] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[134911.988559]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[134911.988589]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[134911.988629]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[134911.988670]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[134911.988705]         ...
[134911.988718] Call Trace:
[134911.988738] [<80b04130>] __schedule+0x438/0xbbc
[134911.988753] [<80b0493c>] schedule+0x88/0x13c
[134911.988766] [<80b08b30>] schedule_timeout+0x200/0x3e8
[134911.988778] [<80b06038>] wait_for_completion+0xa4/0x11c
[134911.988790] [<8006307c>] flush_workqueue+0x124/0x5a4
[134911.988816] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[134911.988835] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[134911.988851] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[134911.988869] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[134911.988881] [<8002d138>] syscall_common+0x34/0x58
[134911.988893] 
[135034.862796] INFO: task rmmod:12470 blocked for more than 983 seconds.
[135034.862814]       Not tainted 5.10.21 #1
[135034.862820] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135034.862827] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[135034.862843] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[135034.862878]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[135034.862910]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[135034.862943]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[135034.862974]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[135034.863011]         ...
[135034.863023] Call Trace:
[135034.863042] [<80b04130>] __schedule+0x438/0xbbc
[135034.863058] [<80b0493c>] schedule+0x88/0x13c
[135034.863071] [<80b08b30>] schedule_timeout+0x200/0x3e8
[135034.863082] [<80b06038>] wait_for_completion+0xa4/0x11c
[135034.863095] [<8006307c>] flush_workqueue+0x124/0x5a4
[135034.863116] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[135034.863134] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[135034.863159] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[135034.863178] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[135034.863190] [<8002d138>] syscall_common+0x34/0x58
[135034.863198] 
[135157.737081] INFO: task rmmod:12470 blocked for more than 1105 seconds.
[135157.737099]       Not tainted 5.10.21 #1
[135157.737107] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135157.737115] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[135157.737144] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[135157.737195]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[135157.737231]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[135157.737264]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[135157.737295]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[135157.737326]         ...
[135157.737337] Call Trace:
[135157.737355] [<80b04130>] __schedule+0x438/0xbbc
[135157.737367] [<80b0493c>] schedule+0x88/0x13c
[135157.737377] [<80b08b30>] schedule_timeout+0x200/0x3e8
[135157.737387] [<80b06038>] wait_for_completion+0xa4/0x11c
[135157.737398] [<8006307c>] flush_workqueue+0x124/0x5a4
[135157.737419] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[135157.737437] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[135157.737453] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[135157.737469] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[135157.737480] [<8002d138>] syscall_common+0x34/0x58
[135157.737489] 
[135280.611354] INFO: task rmmod:12470 blocked for more than 1228 seconds.
[135280.611369]       Not tainted 5.10.21 #1
[135280.611373] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135280.611379] task:rmmod           state:D stack:    0 pid:12470 ppid: 12456 flags:0x00100000
[135280.611393] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b5260 0000024e 00000000
[135280.611423]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe08 00000002 80db0000
[135280.611451]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db0000 80f66474 00000006
[135280.611478]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 00000000 2cc4bd09 7fffffff
[135280.611505]         c2000018 000030b6 00000000 00000000 00000000 00000000 84e55800 a91b9318
[135280.611532]         ...
[135280.611542] Call Trace:
[135280.611557] [<80b04130>] __schedule+0x438/0xbbc
[135280.611567] [<80b0493c>] schedule+0x88/0x13c
[135280.611576] [<80b08b30>] schedule_timeout+0x200/0x3e8
[135280.611585] [<80b06038>] wait_for_completion+0xa4/0x11c
[135280.611596] [<8006307c>] flush_workqueue+0x124/0x5a4
[135280.611615] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
[135280.611630] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_hosted_ng]
[135280.611643] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
[135280.611657] [<800f5534>] sys_delete_module+0x1c4/0x2a8
[135280.611666] [<8002d138>] syscall_common+0x34/0x58


And also, some dmesg log with extra debug `printk`s
```shell
Aug  1 22:03:42 gadget user.err kernel: [133925.234371] esp32_hosted_ng: wait_and_decode_cmd_resp: Command[0x6] time
d out
Aug  1 22:03:42 gadget user.err kernel: [133925.234398] esp32_hosted_ng: cmd_disconnect_request: wait_and_decode_cmd
_resp(priv, cmd_node) failure, ret: -22
Aug  1 22:03:42 gadget user.info kernel: [133925.246584] esp32_hosted_ng: esp_reg_notifier: cfg80211 regulatory doma
in callback for 00, current=<6>[133925.268745] ESP: -> cmd_deinit_interface [0]
Aug  1 22:03:42 gadget user.info kernel: [133925.268759] ESP: -> prepare_command_request()
Aug  1 22:03:42 gadget user.info kernel: [133925.268765] ESP: -> get_free_cmd_node
Aug  1 22:03:42 gadget user.info kernel: [133925.268775] ESP: <- get_free_cmd_node
Aug  1 22:03:42 gadget user.info kernel: [133925.268780] ESP: <- prepare_command_request()
Aug  1 22:03:42 gadget user.info kernel: [133925.268785] ESP: -> queue_cmd_node()
Aug  1 22:03:42 gadget user.info kernel: [133925.268790] ESP: <- pqueue_cmd_node()
Aug  1 22:03:42 gadget user.info kernel: [133925.268794] ESP: -> queue_work()
Aug  1 22:03:42 gadget user.info kernel: [133925.268799] ESP: <- queue_work()
Aug  1 22:03:42 gadget user.info kernel: [133925.268803] ESP: -> wait_and_decode_cmd_resp()
Aug  1 22:03:42 gadget user.info kernel: [133925.268809] ESP: -> wait_event_interruptible_timeout
Aug  2 00:03:47 gadget daemon.info ntpd[1103]: Deleting interface #3 wlan0, 192.168.107.12#123, interface stats: rec
eived=216, sent=222, dropped=0, active_time=74488 secs
Aug  2 00:03:47 gadget daemon.info ntpd[1103]: 162.159.200.1 local addr 192.168.107.12 -> <null>
Aug  2 00:03:47 gadget daemon.info ntpd[1103]: 195.95.153.43 local addr 192.168.107.12 -> <null>
Aug  2 00:03:47 gadget daemon.info ntpd[1103]: 178.215.228.24 local addr 192.168.107.12 -> <null>
Aug  1 22:03:47 gadget user.err kernel: [133930.274131] esp32_hosted_ng: wait_and_decode_cmd_resp: Command[0x12] tim
ed out
Aug  1 22:03:47 gadget user.info kernel: [133930.274136] ESP: <- wait_event_interruptible_timeout
Aug  1 22:03:47 gadget user.err kernel: [133930.274145] esp32_hosted_ng: wait_and_decode_cmd_resp: Command[0x7] time
d out
Aug  1 22:03:47 gadget user.info kernel: [133930.274150] ESP: -> cmd_lock: take
Aug  1 22:03:47 gadget user.err kernel: [133930.274155] esp32_hosted_ng: cmd_set_reg_domain: wait_and_decode_cmd_res
p(priv, cmd_node) failure, ret: -22
Aug  1 22:03:47 gadget user.info kernel: [133930.274160] ESP: -> cmd_lock: release
Aug  1 22:03:47 gadget user.info kernel: [133930.274165] ESP: -> decode_common_resp() 
Aug  1 22:03:47 gadget user.err kernel: [133930.274174] esp32_hosted_ng: cmd_deinit_interface: wait_and_decode_cmd_r
esp(priv, cmd_node) failure, ret: -22
Aug  1 22:03:47 gadget user.info kernel: [133930.274182] ESP: <- cmd_deinit_interface [0]
Aug  1 22:03:47 gadget user.info kernel: [133930.274187] ESP: -> esp_deinit_interface_layer()
Aug  1 22:03:47 gadget user.info kernel: [133930.274192] ESP: -> esp_exit
Aug  1 22:03:48 gadget user.info kernel: [133930.716087] ESP: purging all tx/rx workqueues
Aug  1 22:03:48 gadget user.info kernel: [133930.716101] ESP: purging tx queue 0
Aug  1 22:03:48 gadget user.info kernel: [133930.716108] ESP: purging rx queue 0
Aug  1 22:03:48 gadget user.info kernel: [133930.716113] ESP: purging tx queue 1
Aug  1 22:03:48 gadget user.info kernel: [133930.716117] ESP: purging rx queue 1
Aug  1 22:03:48 gadget user.info kernel: [133930.716122] ESP: purging tx queue 2
Aug  1 22:03:48 gadget user.info kernel: [133930.716268] ESP: purging rx queue 2
Aug  1 22:03:48 gadget user.info kernel: [133930.716277] ESP: purged all tx/rx workqueues
Aug  1 22:03:48 gadget user.info kernel: [133930.716282] ESP: flush spi_workqueue
Aug  1 22:07:52 gadget user.err kernel: [134174.742830] INFO: task rmmod:12470 blocked for more than 122 seconds.
Aug  1 22:07:52 gadget user.err kernel: [134174.742843]       Not tainted 5.10.21 #1
Aug  1 22:07:52 gadget user.err kernel: [134174.742848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables 
this message.
Aug  1 22:07:52 gadget user.info kernel: [134174.742855] task:rmmod           state:D stack:    0 pid:12470 ppid: 12
456 flags:0x00100000
Aug  1 22:07:52 gadget user.info kernel: [134174.742880] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b52
60 0000024e 00000000
Aug  1 22:07:52 gadget user.info kernel: [134174.742932]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe
08 00000002 80db0000
Aug  1 22:07:52 gadget user.info kernel: [134174.742961]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db00
00 80f66474 00000006
Aug  1 22:07:52 gadget user.info kernel: [134174.742988]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 000000
00 2cc4bd09 7fffffff
Aug  1 22:07:52 gadget user.info kernel: [134174.743015]         c2000018 000030b6 00000000 00000000 00000000 000000
00 84e55800 a91b9318
Aug  1 22:07:52 gadget user.info kernel: [134174.743042]         ...
Aug  1 22:07:52 gadget user.info kernel: [134174.743052] Call Trace:
Aug  1 22:07:52 gadget user.info kernel: [134174.743068] [<80b04130>] __schedule+0x438/0xbbc
Aug  1 22:07:52 gadget user.info kernel: [134174.743078] [<80b0493c>] schedule+0x88/0x13c
Aug  1 22:07:52 gadget user.info kernel: [134174.743088] [<80b08b30>] schedule_timeout+0x200/0x3e8
Aug  1 22:07:52 gadget user.info kernel: [134174.743097] [<80b06038>] wait_for_completion+0xa4/0x11c
Aug  1 22:07:52 gadget user.info kernel: [134174.743106] [<8006307c>] flush_workqueue+0x124/0x5a4
Aug  1 22:07:52 gadget user.info kernel: [134174.743126] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
Aug  1 22:07:52 gadget user.info kernel: [134174.743141] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_ho
sted_ng]
Aug  1 22:07:52 gadget user.info kernel: [134174.743155] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
Aug  1 22:07:52 gadget user.info kernel: [134174.743169] [<800f5534>] sys_delete_module+0x1c4/0x2a8
Aug  1 22:07:52 gadget user.info kernel: [134174.743177] [<8002d138>] syscall_common+0x34/0x58
Aug  1 22:07:52 gadget user.warn kernel: [134174.743185] 
Aug  1 22:09:55 gadget user.err kernel: [134297.617125] INFO: task rmmod:12470 blocked for more than 245 seconds.
Aug  1 22:09:55 gadget user.err kernel: [134297.617143]       Not tainted 5.10.21 #1
Aug  1 22:09:55 gadget user.err kernel: [134297.617150] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables 
this message.
Aug  1 22:09:55 gadget user.info kernel: [134297.617157] task:rmmod           state:D stack:    0 pid:12470 ppid: 12
456 flags:0x00100000
Aug  1 22:09:55 gadget user.info kernel: [134297.617175] Stack : 80db0000 00000000 80f70000 800a7860 80dc8380 813b52
60 0000024e 00000000
Aug  1 22:09:55 gadget user.info kernel: [134297.617213]         00000004 a91b9318 80dbcfb4 82b43100 7fffffff 83bcbe
08 00000002 80db0000
Aug  1 22:09:55 gadget user.info kernel: [134297.617250]         c0010000 c0010000 84e55800 80b0493c 80dd0000 80db00
00 80f66474 00000006
Aug  1 22:09:55 gadget user.info kernel: [134297.617298]         83bcbe0c 80b08b30 80f684b4 00000400 0000024d 000000
00 2cc4bd09 7fffffff
Aug  1 22:09:55 gadget user.info kernel: [134297.617345]         c2000018 000030b6 00000000 00000000 00000000 000000
00 84e55800 a91b9318
Aug  1 22:09:55 gadget user.info kernel: [134297.617379]         ...
Aug  1 22:09:55 gadget user.info kernel: [134297.617391] Call Trace:
Aug  1 22:09:55 gadget user.info kernel: [134297.617410] [<80b04130>] __schedule+0x438/0xbbc
Aug  1 22:09:55 gadget user.info kernel: [134297.617424] [<80b0493c>] schedule+0x88/0x13c
Aug  1 22:09:55 gadget user.info kernel: [134297.617437] [<80b08b30>] schedule_timeout+0x200/0x3e8
Aug  1 22:09:55 gadget user.info kernel: [134297.617449] [<80b06038>] wait_for_completion+0xa4/0x11c
Aug  1 22:09:55 gadget user.info kernel: [134297.617461] [<8006307c>] flush_workqueue+0x124/0x5a4
Aug  1 22:09:55 gadget user.info kernel: [134297.617483] [<c0004db8>] spi_exit+0x400/0x424 [esp32_hosted_ng]
Aug  1 22:09:55 gadget user.info kernel: [134297.617502] [<c0005808>] esp_deinit_interface_layer+0x48/0x70 [esp32_ho
sted_ng]
Aug  1 22:09:55 gadget user.info kernel: [134297.617520] [<c001093c>] esp_exit+0x9c/0x10c [esp32_hosted_ng]
Aug  1 22:09:55 gadget user.info kernel: [134297.617539] [<800f5534>] sys_delete_module+0x1c4/0x2a8
Aug  1 22:09:55 gadget user.info kernel: [134297.617552] [<8002d138>] syscall_common+0x34/0x58

Steps to reproduce the behavior

1. Connect to WiFi as normal
2. Operate for several days
3. Wait until the WiFi connection drops
4. Unload the module with rmmod

Project release version

latest

System architecture

other (details in Additional context)

Operating system

Linux

Operating system version

5.10

Shell

ZSH

Additional context

We have around 20 devices continually running to reproduce this. After a few days, one or two random devices will reproduce it.
Note: we are suffering from some WiFi drops. When this happens, we execute a procedure where we remove the module, reload and reconnect. It is possible that both issues are connected.

[mantriyogesh]

I understand the frustration, and there's an issue in the code, as I can confirm from the kernel trace.
Thanks for all the debug logs you have attached.

Connect to WiFi as normal
Operate for several days
Wait until the WiFi connection drops
Unload the module with rmmod

In case there is an easier way to reproduce, it would speed this up.
Anyway, from the context, I would try to reproduce and let you know.

Note: we are suffering from some WiFi drops. When this happens, we execute a procedure where we remove the module, reload and reconnect. It is possible that both issues are connected.

You're right - it's possible these issues are related. Right now, the kernel unload/reload process is the critical issue, so we should address this first. Later, we can focus on the WiFi drop root cause analysis so that such workarounds can be eliminated.

Can you please state the current git commit used on both sides for you? You had stated the latest. I assume it is the latest commit on master on both sides?

[icvidal]

Hi @mantriyogesh, thanks for the quick attention to this issue.

Yesterday we did some progress on this. I suspect there may be some issue in our SPI driver, and the call to spi_sync_transfer in esp_spi_work may occasionally hang indefinitely, locking the task, keeping unfinished work and not allowing anything else to queue work.
At the same time, work is not interruptible so flushing the workqueue also hangs.
We are running some tests to confirm this, but being suspected of a race condition, may take some time.

I think a viable fix would be replacing the spi_sync_transfer for some routine around spi_async with a timeout that can be tailored to the needs of the ESP32<->Host interaction. This would be a bit of a defensive approach, but it'll make it more robust, and I don't see any drawback.
Do you think such approach could be evaluated by your team and eventually merged if it solves this issue?

About the commit, we came back to our working commit (version string 1.0.3.0.12), because that's what we have most of our units and makes it easier to reproduce it.

Finally, if you have any guidance or some idea, we'll be happy to try.

[mantriyogesh]

This looks good. But there is one issue, although. spi_sync_transfer is generally implemented by all the SoCs. I think it would be important if all SoCs implement spi_async or not. As per my experience, I had encountered an SoC earlier, whose lower SPI driver's spi_async() did not work correctly.

Right now, focusing on locating the issue for kernel module load->unload first,

Would you be able to check the observation if we remove c85ecf2?

I meant, the kernel module gets cleaned fine, if this change of yours is removed?

[icvidal]

Good points.
I did see it before the change in c85ecf2, it just wasn't a priority for us at that moment.

[mantriyogesh]

Aug 1 22:03:42 gadget user.info kernel: [133925.268809] ESP: -> wait_event_interruptible_timeout
Aug 2 00:03:47 gadget daemon.info ntpd[1103]: Deleting interface #3 wlan0, 192.168.107.12#123, interface stats: received=216, sent=222, dropped=0, active_time=74488 secs
Aug 2 00:03:47 gadget daemon.info ntpd[1103]: 162.159.200.1 local addr 192.168.107.12 ->
Aug 2 00:03:47 gadget daemon.info ntpd[1103]: 195.95.153.43 local addr 192.168.107.12 ->
Aug 2 00:03:47 gadget daemon.info ntpd[1103]: 178.215.228.24 local addr 192.168.107.12 ->
Aug 1 22:03:47 gadget user.err kernel: [133930.274131] esp32_hosted_ng: wait_and_decode_cmd_resp: Command[0x12] timed out

OR even the very first one,

Aug 1 22:03:42 gadget user.err kernel: [133925.234371] esp32_hosted_ng: wait_and_decode_cmd_resp: Command[0x6] timed out

Why does such a time-out occur in the system? Does the slave receive these events and respond back?
Is the response received but not decodable, because incorrect (bit-shifted buffer possibility?)

Any such 'cmd' is going to trigger esp_send_packet(), which then uses spi_workqueue to send and wait for a response.
it's important not to do 'close_data_path()' very early.

All these are just review comments (even to self) while browsing the code for this specific case.

@Shreyas0-7 is it possible to reproduce this issue reliably at our end?

@icvidal, sorry to bother, but would it be possible to try the latest master once (both sides same commit), if this issue is being reproduced?

[mantriyogesh]

@icvidal ,

Some debug patches to print the transport frames and localise at spi level:

spi.zip

Referece logs:
esp_debug.log
host_debug.log

[mantriyogesh]

@icvidal ?

[icvidal]

Hi @mantriyogesh,
I'm currently low on available devices, and since this issue tends to reproduce over time, I'll schedule a test on a device tomorrow and let it run over the weekend. allocating more devices might help trigger it sooner, but most of them are occupied at the moment.

On your end, I think it's reasonable to lower the severity for now. We have indications that the issue may stem from our SoC's SPI driver. A fix is being tested on a batch of devices, and based on some log messages we added, it appears to be working as expected. That said, given the potential impact, we want to be certain before drawing any conclusions.

I'll follow up once I have either the logs you requested or confirmation that it's specific to our SoC.

For context on our hypothesis:
Whe suspect the spi_sync call is hanging indefinitely under some unknown condition. This blocks esp_spi_work, which in turn causes flush_workqueue to hang during module unload, waiting for the work to complete. If this is correct, it would mean the issue is limited to our SoC. However, if you've seen similar behavior in other environments, I'm happy to help investigate-it's just a bit constrained on my side at the moment, but please, do let me know if that's the case.

[mantriyogesh]

Whe suspect the spi_sync call is hanging indefinitely under some unknown condition. This blocks esp_spi_work, which in turn causes flush_workqueue to hang during module unload, waiting for the work to complete. If this is correct, it would mean the issue is limited to our SoC. However, if you've seen similar behavior in other environments, I'm happy to help investigate-it's just a bit constrained on my side at the moment, but please, do let me know if that's the case.

While I have not observed this, please allow me to come back on this. I will cross-check if our test team had faced such an issue.

[mantriyogesh]

@Shreyas0-7, could you kindly add the recent debug log patch and a base commit to reference? This way, if the issue arises again, we won't have to repeat the process at @icvidal. Thanks a lot!

[Shreyas0-7]

Hey @icvidal please find the patch which will help you debug spi transport
spi.zip

[icvidal]

Hello @mantriyogesh @Shreyas0-7
Our tests confirmed the issue originates in our SoC's SPI driver, not on the ESP32 Hosted NG driver. It's reasonable to close it on your side - can you confirm?

This aligns with our initial hypothesis: spi_sync_transfer blocks due to a fault in our SPI driver which leads to two outcomes: WiFi drops and esp_spi_work stalling, locking spi_workqueue and preventing it from flushing.

After applying the fix on the SPI driver, we've observer neither WiFi drops nor stalled rmmod.

[mantriyogesh]

Thanks for confirming the issue. If possible, could you send us the original file in an open domain, such as https://elixir.bootlin.com/linux/v6.15/source/drivers/spi/spi.c, and the patch you applied for your SoC? This would help us or others working on the same MPU to verify and reference for other SoCs.

[icvidal]

I need to verify if we can redistribute the sources, I'll come back with an answer soon.

[icvidal]

I've lost track of this issue. We can't share the manufacturer SDK but I can explain the fix:
On the SPI driver there was something like this:

int execute_spi_transfer(...) {
  // some preparation steps ...
  prepare_spi_transfer(drvdata, tx_buffer, rx_buffer);
  launch_spi_transfer(drvdata);
  wait_for_completion(drvdata->transfer_complete);
  ...
}

On the IRQ side, there was something like this:

// some checks
if (drvdata->spi->tx_left == 0) {
  complete(drvdata->transfer_complete);
}

Under certain conditions (heavy I/O, lots of events), the IRQ call that signals the completion is either interrupted or completely unserviced. There were some design problems on that SPI driver that the vendor is aware of.

Our solution to work around the permanent lock was to replace the wait_for_completion for a wait_for_completion_interruptible_timeout so the spi transfer becomes something like this:

// some preparation steps ...
prepare_spi_transfer(drvdata, tx_buffer, rx_buffer);
launch_spi_transfer(drvdata);
if (!wait_for_completion_interruptible_timeout(drvdata->transfer_complete, SPI_TRANSFER_TIMEOUT_SEC * HZ)) {
  printk(KERN_WARNING "SPI Transfer Blocked for %d seconds\n", SPI_TRANSFER_TIMEOUT_SEC);
}

We defined SPI_TRANSFER_TIMEOUT_SEC to give us a 5 second limit, enough for all of our use cases.

After this we run a test with 30 devices running for 30 days and we spotted in total a few tens of "SPI Transfer Blocked for 5 seconds" messages on our platform but haven't had any locks.

Having said that, on discussions with the vendor we've been advised to move to a newer SDK version that has a completely new implementation of the SPI driver and many other fixes, along with a newer kernel version.

You can consider this issue closed. There is nothing from this issue that is caused by Espressif's software and since the vendor of our SoC already has a solution, there isn't anything else on their side to do.

As a final highlight: we are very happy with the support you provided and your team's responsiveness.