Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71 #2420

Closed
ccztux opened this issue Mar 6, 2018 · 3 comments
Closed

ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71 #2420

ccztux opened this issue Mar 6, 2018 · 3 comments

Comments

@ccztux
Copy link

ccztux commented Mar 6, 2018

I use the following usb wifi adapter on a raspberry pi 2 as an ap with hostapd:

ALFA Networks AWUS052NH | 2.4 / 5 GHz, USB WLAN Adapter, 300 MBit, Ralink RT3572

Kernel version:

Linux wurlitzer 4.9.59-v7+ #1047 SMP Sun Oct 29 12:19:23 GMT 2017 armv7l GNU/Linux

I have deactivated hardware encryption:

cat /etc/modprobe.d/rt2800usb.conf
options rt2800usb nohwcrypt=1

Ip settings:

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast master br0 state UP group default qlen 1000
    link/ether b8:27:eb:10:21:87 brd ff:ff:ff:ff:ff:ff
3: br0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether e6:66:da:2f:90:72 brd ff:ff:ff:ff:ff:ff
    inet 10.0.0.1/24 brd 10.0.0.255 scope global br0
       valid_lft forever preferred_lft forever
    inet6 fe80::e466:daff:fe2f:9072/64 scope link 
       valid_lft forever preferred_lft forever
5: wlan0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc mq master br0 state DOWN group default qlen 1000
    link/ether 00:c0:ca:8f:c5:44 brd ff:ff:ff:ff:ff:ff

After running hostapd a short time, the connections break and there plenty of this log messages are written to /var/log/messages:

Mar  6 19:31:55 localhost kernel: [77125.660664] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71

Extracted data from /var/log/messages:

Mar  6 19:27:45 localhost kernel: [76874.917882] ieee80211 phy0: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
Mar  6 19:27:45 localhost kernel: [76874.920113] ieee80211 phy0: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.36
Mar  6 19:27:46 localhost kernel: [76876.213589] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Mar  6 19:27:46 localhost kernel: [76876.220073] br0: port 2(wlan0) entered blocking state
Mar  6 19:27:46 localhost kernel: [76876.220089] br0: port 2(wlan0) entered disabled state
Mar  6 19:27:46 localhost kernel: [76876.221142] device wlan0 entered promiscuous mode
Mar  6 19:27:54 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.108 (10.0.0.1) from 60:d9:a0:68:43:6e (android-8c2ed927ce08942b) via br0
Mar  6 19:27:54 localhost dhcpd[490]: DHCPACK on 10.0.0.108 to 60:d9:a0:68:43:6e (android-8c2ed927ce08942b) via br0
Mar  6 19:27:57 localhost kernel: [76887.206972] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Mar  6 19:27:57 localhost kernel: [76887.207133] br0: port 2(wlan0) entered blocking state
Mar  6 19:27:57 localhost kernel: [76887.207141] br0: port 2(wlan0) entered listening state
Mar  6 19:28:12 localhost kernel: [76902.268743] br0: port 2(wlan0) entered learning state
Mar  6 19:28:15 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.20 from 14:91:82:ed:e3:f2 via br0
Mar  6 19:28:15 localhost dhcpd[490]: DHCPACK on 10.0.0.20 to 14:91:82:ed:e3:f2 via br0
Mar  6 19:28:27 localhost kernel: [76917.628872] br0: port 2(wlan0) entered forwarding state
Mar  6 19:28:27 localhost kernel: [76917.628915] br0: topology change detected, sending tcn bpdu
Mar  6 19:28:50 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.43 from b8:27:eb:04:b3:82 via br0
Mar  6 19:28:50 localhost dhcpd[490]: DHCPACK on 10.0.0.43 to b8:27:eb:04:b3:82 via br0
Mar  6 19:28:51 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.41 from d8:9d:67:cd:ae:0e via br0
Mar  6 19:28:51 localhost dhcpd[490]: DHCPACK on 10.0.0.41 to d8:9d:67:cd:ae:0e via br0
Mar  6 19:30:03 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.108 from 60:d9:a0:68:43:6e (android-8c2ed927ce08942b) via br0
Mar  6 19:30:03 localhost dhcpd[490]: DHCPACK on 10.0.0.108 to 60:d9:a0:68:43:6e (android-8c2ed927ce08942b) via br0
Mar  6 19:30:45 localhost dhcpd[490]: DHCPDISCOVER from 84:3a:4b:81:95:44 via br0
Mar  6 19:30:46 localhost dhcpd[490]: DHCPOFFER on 10.0.0.109 to 84:3a:4b:81:95:44 (tux01) via br0
Mar  6 19:30:46 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.109 (10.0.0.1) from 84:3a:4b:81:95:44 (tux01) via br0
Mar  6 19:30:46 localhost dhcpd[490]: DHCPACK on 10.0.0.109 to 84:3a:4b:81:95:44 (tux01) via br0
Mar  6 19:31:26 localhost dhcpd[490]: DHCPDISCOVER from 1c:23:2c:6e:d3:d1 via br0
Mar  6 19:31:27 localhost dhcpd[490]: DHCPOFFER on 10.0.0.112 to 1c:23:2c:6e:d3:d1 (Galaxy-A5-2017) via br0
Mar  6 19:31:28 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.112 (10.0.0.1) from 1c:23:2c:6e:d3:d1 (Galaxy-A5-2017) via br0
Mar  6 19:31:28 localhost dhcpd[490]: DHCPACK on 10.0.0.112 to 1c:23:2c:6e:d3:d1 (Galaxy-A5-2017) via br0
Mar  6 19:31:43 localhost dhcpd[490]: DHCPDISCOVER from 68:63:59:ab:8c:bc via br0
Mar  6 19:31:44 localhost dhcpd[490]: DHCPOFFER on 10.0.0.110 to 68:63:59:ab:8c:bc via br0
Mar  6 19:31:44 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.110 (10.0.0.1) from 68:63:59:ab:8c:bc via br0
Mar  6 19:31:44 localhost dhcpd[490]: DHCPACK on 10.0.0.110 to 68:63:59:ab:8c:bc via br0
Mar  6 19:31:45 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.105 from 00:fc:8b:97:2b:2d via br0
Mar  6 19:31:45 localhost dhcpd[490]: DHCPACK on 10.0.0.105 to 00:fc:8b:97:2b:2d (amazon-052218988) via br0
Mar  6 19:31:55 localhost kernel: [77125.660395] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.660664] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.661381] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.661604] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.661840] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.662023] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:55 localhost kernel: [77125.662254] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
.
.
.
[snip]
.
.
.
Mar  6 19:31:56 localhost kernel: [77125.791302] usb 1-1-port2: over-current change
.
.
.
[snip]
.
.
.
Mar  6 19:31:56 localhost kernel: [77126.031211] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:56 localhost kernel: [77126.031352] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:56 localhost kernel: [77126.031481] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:56 localhost kernel: [77126.031607] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:56 localhost kernel: [77126.031671] usb 1-1.5: USB disconnect, device number 4
Mar  6 19:31:56 localhost kernel: [77126.031738] ieee80211 phy0: rt2800usb_tx_sta_fifo_read_completed: Warning - TX status read failed -71
Mar  6 19:31:56 localhost kernel: [77126.102623] br0: port 2(wlan0) entered disabled state
Mar  6 19:31:56 localhost kernel: [77126.103760] device wlan0 left promiscuous mode
Mar  6 19:31:56 localhost kernel: [77126.103776] br0: port 2(wlan0) entered disabled state
Mar  6 19:31:56 localhost kernel: [77126.660609] usb 1-1.5: new high-speed USB device number 5 using dwc_otg
Mar  6 19:31:57 localhost kernel: [77126.806595] usb 1-1.5: New USB device found, idVendor=148f, idProduct=3572
Mar  6 19:31:57 localhost kernel: [77126.806606] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Mar  6 19:31:57 localhost kernel: [77126.806612] usb 1-1.5: Product: 802.11 n WLAN
Mar  6 19:31:57 localhost kernel: [77126.806619] usb 1-1.5: Manufacturer: Ralink
Mar  6 19:31:57 localhost kernel: [77126.806625] usb 1-1.5: SerialNumber: 1.0
Mar  6 19:31:57 localhost kernel: [77126.910607] usb 1-1.5: reset high-speed USB device number 5 using dwc_otg
Mar  6 19:31:57 localhost kernel: [77127.049749] ieee80211 phy1: rt2x00_set_rt: Info - RT chipset 3572, rev 0223 detected
Mar  6 19:31:57 localhost kernel: [77127.071301] ieee80211 phy1: rt2x00_set_rf: Info - RF chipset 0009 detected
Mar  6 19:31:57 localhost kernel: [77127.076374] ieee80211 phy1: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
Mar  6 19:31:57 localhost kernel: [77127.076473] ieee80211 phy1: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.36
Mar  6 19:31:57 localhost mtp-probe: checking bus 1, device 5: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5"
Mar  6 19:31:57 localhost mtp-probe: bus: 1, device: 5 was not an MTP device
Mar  6 19:31:58 localhost kernel: [77128.363965] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Mar  6 19:31:58 localhost kernel: [77128.450676] br0: port 2(wlan0) entered blocking state
Mar  6 19:31:58 localhost kernel: [77128.450699] br0: port 2(wlan0) entered disabled state
Mar  6 19:31:58 localhost kernel: [77128.451442] device wlan0 entered promiscuous mode
Mar  6 19:32:31 localhost dhcpd[490]: DHCPREQUEST for 10.0.0.10 from 24:5e:be:02:77:d0 via br0
Mar  6 19:32:31 localhost dhcpd[490]: DHCPACK on 10.0.0.10 to 24:5e:be:02:77:d0 via br0

Could this be the issue, of disconnection?:

Mar  6 19:31:56 localhost kernel: [77125.791302] usb 1-1-port2: over-current change

What's it all about the excessive logging?

I have tested this also with the newest kernel version, updated via raspi-config, but the error still exists. Now I have reinstalled the rasbpian stock kernel.

Please let me know, if I should provide more infos.
@rodizio1
Copy link

rodizio1 commented Mar 9, 2018

That card is very power hungry, it creates a high current spike (above 1.3 amps) when the interface is brought up and pulls up to 2 amps (yes, 10 Watts) when transmitting.

You need a good power supply and short good quality USB cables to rule out power-supply problems first.

@pelwell
Copy link
Contributor

pelwell commented Mar 9, 2018

Thanks for your insight, @rodizio1.

@ccztux
Copy link
Author

ccztux commented Mar 9, 2018

Thank you for pointing this out! I will use another USB wifi adapter.

@ccztux ccztux closed this as completed Mar 9, 2018
popcornmix pushed a commit that referenced this issue Nov 22, 2021
@rafaeljw @gregkh
PM: sleep: Avoid calling put_device() under dpm_list_mtx
051d89f 
commit 2aa3660 upstream.

It is generally unsafe to call put_device() with dpm_list_mtx held,
because the given device's release routine may carry out an action
depending on that lock which then may deadlock, so modify the
system-wide suspend and resume of devices to always drop dpm_list_mtx
before calling put_device() (and adjust white space somewhat while
at it).

For instance, this prevents the following splat from showing up in
the kernel log after a system resume in certain configurations:

[ 3290.969514] ======================================================
[ 3290.969517] WARNING: possible circular locking dependency detected
[ 3290.969519] 5.15.0+ #2420 Tainted: G S
[ 3290.969523] ------------------------------------------------------
[ 3290.969525] systemd-sleep/4553 is trying to acquire lock:
[ 3290.969529] ffff888117ab1138 ((wq_completion)hci0#2){+.+.}-{0:0}, at: flush_workqueue+0x87/0x4a0
[ 3290.969554]
               but task is already holding lock:
[ 3290.969556] ffffffff8280fca8 (dpm_list_mtx){+.+.}-{3:3}, at: dpm_resume+0x12e/0x3e0
[ 3290.969571]
               which lock already depends on the new lock.

[ 3290.969573]
               the existing dependency chain (in reverse order) is:
[ 3290.969575]
               -> #3 (dpm_list_mtx){+.+.}-{3:3}:
[ 3290.969583]        __mutex_lock+0x9d/0xa30
[ 3290.969591]        device_pm_add+0x2e/0xe0
[ 3290.969597]        device_add+0x4d5/0x8f0
[ 3290.969605]        hci_conn_add_sysfs+0x43/0xb0 [bluetooth]
[ 3290.969689]        hci_conn_complete_evt.isra.71+0x124/0x750 [bluetooth]
[ 3290.969747]        hci_event_packet+0xd6c/0x28a0 [bluetooth]
[ 3290.969798]        hci_rx_work+0x213/0x640 [bluetooth]
[ 3290.969842]        process_one_work+0x2aa/0x650
[ 3290.969851]        worker_thread+0x39/0x400
[ 3290.969859]        kthread+0x142/0x170
[ 3290.969865]        ret_from_fork+0x22/0x30
[ 3290.969872]
               -> #2 (&hdev->lock){+.+.}-{3:3}:
[ 3290.969881]        __mutex_lock+0x9d/0xa30
[ 3290.969887]        hci_event_packet+0xba/0x28a0 [bluetooth]
[ 3290.969935]        hci_rx_work+0x213/0x640 [bluetooth]
[ 3290.969978]        process_one_work+0x2aa/0x650
[ 3290.969985]        worker_thread+0x39/0x400
[ 3290.969993]        kthread+0x142/0x170
[ 3290.969999]        ret_from_fork+0x22/0x30
[ 3290.970004]
               -> #1 ((work_completion)(&hdev->rx_work)){+.+.}-{0:0}:
[ 3290.970013]        process_one_work+0x27d/0x650
[ 3290.970020]        worker_thread+0x39/0x400
[ 3290.970028]        kthread+0x142/0x170
[ 3290.970033]        ret_from_fork+0x22/0x30
[ 3290.970038]
               -> #0 ((wq_completion)hci0#2){+.+.}-{0:0}:
[ 3290.970047]        __lock_acquire+0x15cb/0x1b50
[ 3290.970054]        lock_acquire+0x26c/0x300
[ 3290.970059]        flush_workqueue+0xae/0x4a0
[ 3290.970066]        drain_workqueue+0xa1/0x130
[ 3290.970073]        destroy_workqueue+0x34/0x1f0
[ 3290.970081]        hci_release_dev+0x49/0x180 [bluetooth]
[ 3290.970130]        bt_host_release+0x1d/0x30 [bluetooth]
[ 3290.970195]        device_release+0x33/0x90
[ 3290.970201]        kobject_release+0x63/0x160
[ 3290.970211]        dpm_resume+0x164/0x3e0
[ 3290.970215]        dpm_resume_end+0xd/0x20
[ 3290.970220]        suspend_devices_and_enter+0x1a4/0xba0
[ 3290.970229]        pm_suspend+0x26b/0x310
[ 3290.970236]        state_store+0x42/0x90
[ 3290.970243]        kernfs_fop_write_iter+0x135/0x1b0
[ 3290.970251]        new_sync_write+0x125/0x1c0
[ 3290.970257]        vfs_write+0x360/0x3c0
[ 3290.970263]        ksys_write+0xa7/0xe0
[ 3290.970269]        do_syscall_64+0x3a/0x80
[ 3290.970276]        entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 3290.970284]
               other info that might help us debug this:

[ 3290.970285] Chain exists of:
                 (wq_completion)hci0#2 --> &hdev->lock --> dpm_list_mtx

[ 3290.970297]  Possible unsafe locking scenario:

[ 3290.970299]        CPU0                    CPU1
[ 3290.970300]        ----                    ----
[ 3290.970302]   lock(dpm_list_mtx);
[ 3290.970306]                                lock(&hdev->lock);
[ 3290.970310]                                lock(dpm_list_mtx);
[ 3290.970314]   lock((wq_completion)hci0#2);
[ 3290.970319]
                *** DEADLOCK ***

[ 3290.970321] 7 locks held by systemd-sleep/4553:
[ 3290.970325]  #0: ffff888103bcd448 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0xa7/0xe0
[ 3290.970341]  #1: ffff888115a14488 (&of->mutex){+.+.}-{3:3}, at: kernfs_fop_write_iter+0x103/0x1b0
[ 3290.970355]  #2: ffff888100f719e0 (kn->active#233){.+.+}-{0:0}, at: kernfs_fop_write_iter+0x10c/0x1b0
[ 3290.970369]  #3: ffffffff82661048 (autosleep_lock){+.+.}-{3:3}, at: state_store+0x12/0x90
[ 3290.970384]  #4: ffffffff82658ac8 (system_transition_mutex){+.+.}-{3:3}, at: pm_suspend+0x9f/0x310
[ 3290.970399]  #5: ffffffff827f2a48 (acpi_scan_lock){+.+.}-{3:3}, at: acpi_suspend_begin+0x4c/0x80
[ 3290.970416]  #6: ffffffff8280fca8 (dpm_list_mtx){+.+.}-{3:3}, at: dpm_resume+0x12e/0x3e0
[ 3290.970428]
               stack backtrace:
[ 3290.970431] CPU: 3 PID: 4553 Comm: systemd-sleep Tainted: G S                5.15.0+ #2420
[ 3290.970438] Hardware name: Dell Inc. XPS 13 9380/0RYJWW, BIOS 1.5.0 06/03/2019
[ 3290.970441] Call Trace:
[ 3290.970446]  dump_stack_lvl+0x44/0x57
[ 3290.970454]  check_noncircular+0x105/0x120
[ 3290.970468]  ? __lock_acquire+0x15cb/0x1b50
[ 3290.970474]  __lock_acquire+0x15cb/0x1b50
[ 3290.970487]  lock_acquire+0x26c/0x300
[ 3290.970493]  ? flush_workqueue+0x87/0x4a0
[ 3290.970503]  ? __raw_spin_lock_init+0x3b/0x60
[ 3290.970510]  ? lockdep_init_map_type+0x58/0x240
[ 3290.970519]  flush_workqueue+0xae/0x4a0
[ 3290.970526]  ? flush_workqueue+0x87/0x4a0
[ 3290.970544]  ? drain_workqueue+0xa1/0x130
[ 3290.970552]  drain_workqueue+0xa1/0x130
[ 3290.970561]  destroy_workqueue+0x34/0x1f0
[ 3290.970572]  hci_release_dev+0x49/0x180 [bluetooth]
[ 3290.970624]  bt_host_release+0x1d/0x30 [bluetooth]
[ 3290.970687]  device_release+0x33/0x90
[ 3290.970695]  kobject_release+0x63/0x160
[ 3290.970705]  dpm_resume+0x164/0x3e0
[ 3290.970710]  ? dpm_resume_early+0x251/0x3b0
[ 3290.970718]  dpm_resume_end+0xd/0x20
[ 3290.970723]  suspend_devices_and_enter+0x1a4/0xba0
[ 3290.970737]  pm_suspend+0x26b/0x310
[ 3290.970746]  state_store+0x42/0x90
[ 3290.970755]  kernfs_fop_write_iter+0x135/0x1b0
[ 3290.970764]  new_sync_write+0x125/0x1c0
[ 3290.970777]  vfs_write+0x360/0x3c0
[ 3290.970785]  ksys_write+0xa7/0xe0
[ 3290.970794]  do_syscall_64+0x3a/0x80
[ 3290.970803]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 3290.970811] RIP: 0033:0x7f41b1328164
[ 3290.970819] Code: 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 80 00 00 00 00 8b 05 4a d2 2c 00 48 63 ff 85 c0 75 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 f3 c3 66 90 55 53 48 89 d5 48 89 f3 48 83
[ 3290.970824] RSP: 002b:00007ffe6ae21b28 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 3290.970831] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f41b1328164
[ 3290.970836] RDX: 0000000000000004 RSI: 000055965e651070 RDI: 0000000000000004
[ 3290.970839] RBP: 000055965e651070 R08: 000055965e64f390 R09: 00007f41b1e3d1c0
[ 3290.970843] R10: 000000000000000a R11: 0000000000000246 R12: 0000000000000004
[ 3290.970846] R13: 0000000000000001 R14: 000055965e64f2b0 R15: 0000000000000004

Cc: All applicable <[email protected]>
Signed-off-by: Rafael J. Wysocki <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
popcornmix pushed a commit that referenced this issue Nov 29, 2021
@rafaeljw @gregkh
PM: sleep: Avoid calling put_device() under dpm_list_mtx
e554c13 
commit 2aa3660 upstream.

It is generally unsafe to call put_device() with dpm_list_mtx held,
because the given device's release routine may carry out an action
depending on that lock which then may deadlock, so modify the
system-wide suspend and resume of devices to always drop dpm_list_mtx
before calling put_device() (and adjust white space somewhat while
at it).

For instance, this prevents the following splat from showing up in
the kernel log after a system resume in certain configurations:

[ 3290.969514] ======================================================
[ 3290.969517] WARNING: possible circular locking dependency detected
[ 3290.969519] 5.15.0+ #2420 Tainted: G S
[ 3290.969523] ------------------------------------------------------
[ 3290.969525] systemd-sleep/4553 is trying to acquire lock:
[ 3290.969529] ffff888117ab1138 ((wq_completion)hci0#2){+.+.}-{0:0}, at: flush_workqueue+0x87/0x4a0
[ 3290.969554]
               but task is already holding lock:
[ 3290.969556] ffffffff8280fca8 (dpm_list_mtx){+.+.}-{3:3}, at: dpm_resume+0x12e/0x3e0
[ 3290.969571]
               which lock already depends on the new lock.

[ 3290.969573]
               the existing dependency chain (in reverse order) is:
[ 3290.969575]
               -> #3 (dpm_list_mtx){+.+.}-{3:3}:
[ 3290.969583]        __mutex_lock+0x9d/0xa30
[ 3290.969591]        device_pm_add+0x2e/0xe0
[ 3290.969597]        device_add+0x4d5/0x8f0
[ 3290.969605]        hci_conn_add_sysfs+0x43/0xb0 [bluetooth]
[ 3290.969689]        hci_conn_complete_evt.isra.71+0x124/0x750 [bluetooth]
[ 3290.969747]        hci_event_packet+0xd6c/0x28a0 [bluetooth]
[ 3290.969798]        hci_rx_work+0x213/0x640 [bluetooth]
[ 3290.969842]        process_one_work+0x2aa/0x650
[ 3290.969851]        worker_thread+0x39/0x400
[ 3290.969859]        kthread+0x142/0x170
[ 3290.969865]        ret_from_fork+0x22/0x30
[ 3290.969872]
               -> #2 (&hdev->lock){+.+.}-{3:3}:
[ 3290.969881]        __mutex_lock+0x9d/0xa30
[ 3290.969887]        hci_event_packet+0xba/0x28a0 [bluetooth]
[ 3290.969935]        hci_rx_work+0x213/0x640 [bluetooth]
[ 3290.969978]        process_one_work+0x2aa/0x650
[ 3290.969985]        worker_thread+0x39/0x400
[ 3290.969993]        kthread+0x142/0x170
[ 3290.969999]        ret_from_fork+0x22/0x30
[ 3290.970004]
               -> #1 ((work_completion)(&hdev->rx_work)){+.+.}-{0:0}:
[ 3290.970013]        process_one_work+0x27d/0x650
[ 3290.970020]        worker_thread+0x39/0x400
[ 3290.970028]        kthread+0x142/0x170
[ 3290.970033]        ret_from_fork+0x22/0x30
[ 3290.970038]
               -> #0 ((wq_completion)hci0#2){+.+.}-{0:0}:
[ 3290.970047]        __lock_acquire+0x15cb/0x1b50
[ 3290.970054]        lock_acquire+0x26c/0x300
[ 3290.970059]        flush_workqueue+0xae/0x4a0
[ 3290.970066]        drain_workqueue+0xa1/0x130
[ 3290.970073]        destroy_workqueue+0x34/0x1f0
[ 3290.970081]        hci_release_dev+0x49/0x180 [bluetooth]
[ 3290.970130]        bt_host_release+0x1d/0x30 [bluetooth]
[ 3290.970195]        device_release+0x33/0x90
[ 3290.970201]        kobject_release+0x63/0x160
[ 3290.970211]        dpm_resume+0x164/0x3e0
[ 3290.970215]        dpm_resume_end+0xd/0x20
[ 3290.970220]        suspend_devices_and_enter+0x1a4/0xba0
[ 3290.970229]        pm_suspend+0x26b/0x310
[ 3290.970236]        state_store+0x42/0x90
[ 3290.970243]        kernfs_fop_write_iter+0x135/0x1b0
[ 3290.970251]        new_sync_write+0x125/0x1c0
[ 3290.970257]        vfs_write+0x360/0x3c0
[ 3290.970263]        ksys_write+0xa7/0xe0
[ 3290.970269]        do_syscall_64+0x3a/0x80
[ 3290.970276]        entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 3290.970284]
               other info that might help us debug this:

[ 3290.970285] Chain exists of:
                 (wq_completion)hci0#2 --> &hdev->lock --> dpm_list_mtx

[ 3290.970297]  Possible unsafe locking scenario:

[ 3290.970299]        CPU0                    CPU1
[ 3290.970300]        ----                    ----
[ 3290.970302]   lock(dpm_list_mtx);
[ 3290.970306]                                lock(&hdev->lock);
[ 3290.970310]                                lock(dpm_list_mtx);
[ 3290.970314]   lock((wq_completion)hci0#2);
[ 3290.970319]
                *** DEADLOCK ***

[ 3290.970321] 7 locks held by systemd-sleep/4553:
[ 3290.970325]  #0: ffff888103bcd448 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0xa7/0xe0
[ 3290.970341]  #1: ffff888115a14488 (&of->mutex){+.+.}-{3:3}, at: kernfs_fop_write_iter+0x103/0x1b0
[ 3290.970355]  #2: ffff888100f719e0 (kn->active#233){.+.+}-{0:0}, at: kernfs_fop_write_iter+0x10c/0x1b0
[ 3290.970369]  #3: ffffffff82661048 (autosleep_lock){+.+.}-{3:3}, at: state_store+0x12/0x90
[ 3290.970384]  #4: ffffffff82658ac8 (system_transition_mutex){+.+.}-{3:3}, at: pm_suspend+0x9f/0x310
[ 3290.970399]  #5: ffffffff827f2a48 (acpi_scan_lock){+.+.}-{3:3}, at: acpi_suspend_begin+0x4c/0x80
[ 3290.970416]  #6: ffffffff8280fca8 (dpm_list_mtx){+.+.}-{3:3}, at: dpm_resume+0x12e/0x3e0
[ 3290.970428]
               stack backtrace:
[ 3290.970431] CPU: 3 PID: 4553 Comm: systemd-sleep Tainted: G S                5.15.0+ #2420
[ 3290.970438] Hardware name: Dell Inc. XPS 13 9380/0RYJWW, BIOS 1.5.0 06/03/2019
[ 3290.970441] Call Trace:
[ 3290.970446]  dump_stack_lvl+0x44/0x57
[ 3290.970454]  check_noncircular+0x105/0x120
[ 3290.970468]  ? __lock_acquire+0x15cb/0x1b50
[ 3290.970474]  __lock_acquire+0x15cb/0x1b50
[ 3290.970487]  lock_acquire+0x26c/0x300
[ 3290.970493]  ? flush_workqueue+0x87/0x4a0
[ 3290.970503]  ? __raw_spin_lock_init+0x3b/0x60
[ 3290.970510]  ? lockdep_init_map_type+0x58/0x240
[ 3290.970519]  flush_workqueue+0xae/0x4a0
[ 3290.970526]  ? flush_workqueue+0x87/0x4a0
[ 3290.970544]  ? drain_workqueue+0xa1/0x130
[ 3290.970552]  drain_workqueue+0xa1/0x130
[ 3290.970561]  destroy_workqueue+0x34/0x1f0
[ 3290.970572]  hci_release_dev+0x49/0x180 [bluetooth]
[ 3290.970624]  bt_host_release+0x1d/0x30 [bluetooth]
[ 3290.970687]  device_release+0x33/0x90
[ 3290.970695]  kobject_release+0x63/0x160
[ 3290.970705]  dpm_resume+0x164/0x3e0
[ 3290.970710]  ? dpm_resume_early+0x251/0x3b0
[ 3290.970718]  dpm_resume_end+0xd/0x20
[ 3290.970723]  suspend_devices_and_enter+0x1a4/0xba0
[ 3290.970737]  pm_suspend+0x26b/0x310
[ 3290.970746]  state_store+0x42/0x90
[ 3290.970755]  kernfs_fop_write_iter+0x135/0x1b0
[ 3290.970764]  new_sync_write+0x125/0x1c0
[ 3290.970777]  vfs_write+0x360/0x3c0
[ 3290.970785]  ksys_write+0xa7/0xe0
[ 3290.970794]  do_syscall_64+0x3a/0x80
[ 3290.970803]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 3290.970811] RIP: 0033:0x7f41b1328164
[ 3290.970819] Code: 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 80 00 00 00 00 8b 05 4a d2 2c 00 48 63 ff 85 c0 75 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 f3 c3 66 90 55 53 48 89 d5 48 89 f3 48 83
[ 3290.970824] RSP: 002b:00007ffe6ae21b28 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 3290.970831] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f41b1328164
[ 3290.970836] RDX: 0000000000000004 RSI: 000055965e651070 RDI: 0000000000000004
[ 3290.970839] RBP: 000055965e651070 R08: 000055965e64f390 R09: 00007f41b1e3d1c0
[ 3290.970843] R10: 000000000000000a R11: 0000000000000246 R12: 0000000000000004
[ 3290.970846] R13: 0000000000000001 R14: 000055965e64f2b0 R15: 0000000000000004

Cc: All applicable <[email protected]>
Signed-off-by: Rafael J. Wysocki <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@pelwell @ccztux @rodizio1