On Thu, Feb 10, 2022 at 6:44 PM Chris Murphy <lists@xxxxxxxxxxxxxxxxx> wrote:
> Case 2:
>
> Bus 001 Device 005: ID 8087:0aaa Intel Corp. Bluetooth 9460/9560
> Jefferson Peak (JfP)
Comparing 5.16.9 (working) and 5.17.0-rc7 (non-working) on this
Thinkpad X1 Carbon, I'm seeing two notable differences:
Multiple messages like this:
[ 15.731405] kernel: Bluetooth: hci0: unexpected event 0xff length: 5 > 0
And a lockdep warning:
[ 26.658252] kernel: Chain exists of:
sk_lock-AF_BLUETOOTH-BTPROTO_RFCOMM -->
rfcomm_mutex --> &d->lock
5.17.0-0.rc4.96.fc36.x86_64+debug
[ 11.210423] systemd[1]: unit_file_build_name_map: alias:
/etc/systemd/system/dbus-org.bluez.service → bluetooth.service
[ 11.222138] systemd[1]: unit_file_build_name_map: normal unit file:
/usr/lib/systemd/system/bluetooth.service
[ 11.222142] systemd[1]: unit_file_build_name_map: normal unit file:
/usr/lib/systemd/system/bluetooth.target
[ 13.403381] kernel: thinkpad_acpi: rfkill switch
tpacpi_bluetooth_sw: radio is unblocked
[ 13.723178] kernel: Bluetooth: Core ver 2.22
[ 13.726055] kernel: NET: Registered PF_BLUETOOTH protocol family
[ 13.728463] kernel: Bluetooth: HCI device and connection manager initialized
[ 13.730914] kernel: Bluetooth: HCI socket layer initialized
[ 13.734079] kernel: Bluetooth: L2CAP socket layer initialized
[ 13.736746] kernel: Bluetooth: SCO socket layer initialized
[ 14.017250] kernel: Bluetooth: hci0: Bootloader revision 0.1 build
42 week 52 2015
[ 14.023991] kernel: Bluetooth: hci0: Device revision is 2
[ 14.026848] kernel: Bluetooth: hci0: Secure boot is enabled
[ 14.029674] kernel: Bluetooth: hci0: OTP lock is enabled
[ 14.032315] kernel: Bluetooth: hci0: API lock is enabled
[ 14.035066] kernel: Bluetooth: hci0: Debug lock is disabled
[ 14.037744] kernel: Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[ 14.091618] kernel: Bluetooth: hci0: Found device firmware:
intel/ibt-17-16-1.sfi
[ 14.093532] kernel: Bluetooth: hci0: Boot Address: 0x40800
[ 14.095001] kernel: Bluetooth: hci0: Firmware Version: 86-46.21
[ 14.538285] kernel: Modules linked in: acpi_cpufreq(-)
snd_hda_codec_hdmi intel_tcc_cooling x86_pkg_temp_thermal
intel_powerclamp snd_hda_codec_realtek coretemp snd_hda_codec_generic
kvm_intel snd_sof_pci_intel_cnl snd_sof_intel_hda_common kvm
soundwire_intel soundwire_generic_allocation soundwire_cadence
snd_sof_intel_hda snd_sof_pci snd_sof_xtensa_dsp snd_sof soundwire_bus
irqbypass rapl snd_soc_skl intel_cstate snd_soc_hdac_hda intel_uncore
snd_hda_ext_core snd_soc_sst_ipc snd_soc_sst_dsp
snd_soc_acpi_intel_match snd_soc_acpi snd_soc_core snd_compress
ac97_bus iwlmvm snd_pcm_dmaengine snd_hda_intel snd_intel_dspcfg
snd_intel_sdw_acpi snd_hda_codec mac80211 snd_hda_core snd_hwdep
snd_seq snd_seq_device btusb think_lmi(+) snd_pcm
firmware_attributes_class libarc4 wmi_bmof intel_wmi_thunderbolt btrtl
i2c_i801 snd_timer uvcvideo i2c_smbus btbcm btintel videobuf2_vmalloc
videobuf2_memops iwlwifi btmtk videobuf2_v4l2 videobuf2_common
thunderbolt bluetooth videodev joydev cfg80211
[ 15.730572] kernel: Bluetooth: hci0: Waiting for firmware download
to complete
[ 15.731394] kernel: Bluetooth: hci0: Firmware loaded in 1599609 usecs
[ 15.731405] kernel: Bluetooth: hci0: unexpected event 0xff length: 5 > 0
[ 15.732383] kernel: Bluetooth: hci0: Waiting for device to boot
[ 15.745966] kernel: Bluetooth: hci0: unexpected event 0xff length: 7 > 0
[ 15.745981] kernel: Bluetooth: hci0: Device booted in 13808 usecs
[ 15.754072] kernel: Bluetooth: hci0: Found Intel DDC parameters:
intel/ibt-17-16-1.ddc
[ 15.761008] kernel: Bluetooth: hci0: Applying Intel DDC parameters completed
[ 15.761991] kernel: Bluetooth: hci0: Firmware revision 0.1 build 86
week 46 2021
[ 16.172456] kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 16.172460] kernel: Bluetooth: BNEP filters: protocol multicast
[ 16.172471] kernel: Bluetooth: BNEP socket layer initialized
[ 21.136887] kernel: Bluetooth: RFCOMM TTY layer initialized
[ 21.136911] kernel: Bluetooth: RFCOMM socket layer initialized
[ 21.137263] kernel: Bluetooth: RFCOMM ver 1.11
[ 26.492364] kernel: Bluetooth: hci0: unexpected event 0xff length: 4 > 0
[ 26.657785] kernel:
[ 26.657800] kernel: ======================================================
[ 26.657806] kernel: WARNING: possible circular locking dependency detected
[ 26.657812] kernel: 5.17.0-0.rc4.96.fc36.x86_64+debug #1 Tainted: G
W --------- ---
[ 26.657820] kernel: ------------------------------------------------------
[ 26.657824] kernel: krfcommd/1391 is trying to acquire lock:
[ 26.657831] kernel: ffff8d697a534940
(sk_lock-AF_BLUETOOTH-BTPROTO_RFCOMM){+.+.}-{0:0}, at:
rfcomm_sk_state_change+0x4d/0x110 [rfcomm]
[ 26.657879] kernel:
but task is already holding lock:
[ 26.657884] kernel: ffff8d695be69540 (&d->lock){+.+.}-{3:3}, at:
__rfcomm_dlc_close+0x8b/0x230 [rfcomm]
[ 26.657920] kernel:
which lock already depends on the new lock.
[ 26.657924] kernel:
the existing dependency chain (in reverse order) is:
[ 26.657929] kernel:
-> #2 (&d->lock){+.+.}-{3:3}:
[ 26.657945] kernel: __mutex_lock+0x93/0x7d0
[ 26.657958] kernel: __rfcomm_dlc_close+0x8b/0x230 [rfcomm]
[ 26.657985] kernel: rfcomm_session_close+0x42/0x90 [rfcomm]
[ 26.658012] kernel: rfcomm_run+0x61a/0x1860 [rfcomm]
[ 26.658038] kernel: kthread+0xf2/0x120
[ 26.658049] kernel: ret_from_fork+0x1f/0x30
[ 26.658059] kernel:
-> #1 (rfcomm_mutex){+.+.}-{3:3}:
[ 26.658069] kernel: __mutex_lock+0x93/0x7d0
[ 26.658075] kernel: rfcomm_dlc_open+0x30/0x340 [rfcomm]
[ 26.658090] kernel: rfcomm_sock_connect+0xd4/0x130 [rfcomm]
[ 26.658106] kernel: __sys_connect+0x8c/0xb0
[ 26.658116] kernel: __x64_sys_connect+0x14/0x20
[ 26.658125] kernel: do_syscall_64+0x37/0x80
[ 26.658134] kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 26.658143] kernel:
-> #0 (sk_lock-AF_BLUETOOTH-BTPROTO_RFCOMM){+.+.}-{0:0}:
[ 26.658152] kernel: __lock_acquire+0x12b5/0x1ec0
[ 26.658161] kernel: lock_acquire+0xd0/0x2d0
[ 26.658167] kernel: lock_sock_nested+0x2e/0x80
[ 26.658174] kernel: rfcomm_sk_state_change+0x4d/0x110 [rfcomm]
[ 26.658189] kernel: __rfcomm_dlc_close+0xa4/0x230 [rfcomm]
[ 26.658204] kernel: rfcomm_session_close+0x42/0x90 [rfcomm]
[ 26.658218] kernel: rfcomm_run+0x61a/0x1860 [rfcomm]
[ 26.658233] kernel: kthread+0xf2/0x120
[ 26.658239] kernel: ret_from_fork+0x1f/0x30
[ 26.658248] kernel:
other info that might help us debug this:
[ 26.658252] kernel: Chain exists of:
sk_lock-AF_BLUETOOTH-BTPROTO_RFCOMM -->
rfcomm_mutex --> &d->lock
[ 26.658264] kernel: Possible unsafe locking scenario:
[ 26.658267] kernel: CPU0 CPU1
[ 26.658270] kernel: ---- ----
[ 26.658272] kernel: lock(&d->lock);
[ 26.658278] kernel: lock(rfcomm_mutex);
[ 26.658283] kernel: lock(&d->lock);
[ 26.658289] kernel: lock(sk_lock-AF_BLUETOOTH-BTPROTO_RFCOMM);
[ 26.658294] kernel:
*** DEADLOCK ***
[ 26.658297] kernel: 2 locks held by krfcommd/1391:
[ 26.658302] kernel: #0: ffffffffc162b130
(rfcomm_mutex){+.+.}-{3:3}, at: rfcomm_run+0x135/0x1860 [rfcomm]
[ 26.658327] kernel: #1: ffff8d695be69540 (&d->lock){+.+.}-{3:3},
at: __rfcomm_dlc_close+0x8b/0x230 [rfcomm]
[ 26.658350] kernel:
stack backtrace:
[ 26.658354] kernel: CPU: 2 PID: 1391 Comm: krfcommd Tainted: G
W --------- --- 5.17.0-0.rc4.96.fc36.x86_64+debug #1
[ 26.658363] kernel: Hardware name: LENOVO 20QDS3E200/20QDS3E200,
BIOS N2HET66W (1.49 ) 11/10/2021
[ 26.658368] kernel: Call Trace:
[ 26.658373] kernel: <TASK>
[ 26.658380] kernel: dump_stack_lvl+0x5e/0x77
[ 26.658392] kernel: check_noncircular+0xdc/0x100
[ 26.658400] kernel: ? asm_sysvec_apic_timer_interrupt+0x12/0x20
[ 26.658416] kernel: __lock_acquire+0x12b5/0x1ec0
[ 26.658429] kernel: lock_acquire+0xd0/0x2d0
[ 26.658438] kernel: ? rfcomm_sk_state_change+0x4d/0x110 [rfcomm]
[ 26.658455] kernel: ? __mutex_lock+0xe7/0x7d0
[ 26.658463] kernel: ? __rfcomm_dlc_close+0x8b/0x230 [rfcomm]
[ 26.658480] kernel: ? rfcomm_check_accept+0xa0/0xa0 [rfcomm]
[ 26.658495] kernel: lock_sock_nested+0x2e/0x80
[ 26.658503] kernel: ? rfcomm_sk_state_change+0x4d/0x110 [rfcomm]
[ 26.658518] kernel: rfcomm_sk_state_change+0x4d/0x110 [rfcomm]
[ 26.658535] kernel: __rfcomm_dlc_close+0xa4/0x230 [rfcomm]
[ 26.658552] kernel: rfcomm_session_close+0x42/0x90 [rfcomm]
[ 26.658569] kernel: rfcomm_run+0x61a/0x1860 [rfcomm]
[ 26.658584] kernel: ? sched_clock_cpu+0xb/0xc0
[ 26.658598] kernel: ? __init_waitqueue_head+0x60/0x60
[ 26.658614] kernel: ? _raw_spin_unlock_irqrestore+0x41/0x60
[ 26.658625] kernel: ? rfcomm_check_accept+0xa0/0xa0 [rfcomm]
[ 26.658640] kernel: kthread+0xf2/0x120
[ 26.658647] kernel: ? kthread_complete_and_exit+0x20/0x20
[ 26.658657] kernel: ret_from_fork+0x1f/0x30
[ 26.658675] kernel: </TASK>
[ 167.235571] kernel: Bluetooth: hci0: unexpected event 0xff length: 4 > 0
[ 190.233772] kernel: Bluetooth: hci0: unexpected event 0xff length: 4 > 0
[ 190.433812] kernel: Bluetooth: hci0: Opcode 0x 401 failed: -16
[ 194.234441] kernel: Bluetooth: hci0: unexpected event 0xff length: 4 > 0
[ 199.234214] kernel: Bluetooth: hci0: unexpected event 0xff length: 4 > 0
--
Chris Murphy
