#995399 bluez: bluetooth disable after few seconds

Package:
bluez
Source:
bluez
Description:
Bluetooth tools and daemons
Submitter:
Stefano Callegari
Date:
2024-01-22 12:51:06 UTC
Severity:
important
#995399#5
Date:
2021-09-30 15:50:18 UTC
From:
To:
Dear Maintainer,

from 2 days when I try to connect a bluetooth device paired (2 mouse) the
daemon hangs (system settings tell me it's disconnected, in kde tray the
icon disappear).

After few seconds the BT auto restart and connects the mouse. If I use the
mouse the BT works, but when I stop to move the mouse (for example)
for few seconds, just I move it again the BT repeat the loop.

Also the add wizard is unusable: the BT hangs repeatedly.

Thinkig some time out problems, I've tried:
1) put in black list the USB address in tlp;
2) stop tlp;
3) stop upower;
4) restart bluetooth.

Nothing solve.

If I don't use BT devices, the BT hangs again but rarely.

From /var/log/syslog

Sep 30 17:05:37 G5045 kernel: [21749.597087] usb 2-1.3: USB disconnect, device number 57
Sep 30 17:05:37 G5045 kernel: [21749.688289] usb 2-1.3: new full-speed USB device number 58 using ehci-pci
Sep 30 17:05:37 G5045 kernel: [21749.797459] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.01
Sep 30 17:05:37 G5045 kernel: [21749.797472] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:05:37 G5045 kernel: [21749.799241] usb 2-1.3: firmware: direct-loading firmware ar3k/ramps_0x31010000_40.dfu
Sep 30 17:05:37 G5045 NetworkManager[1212]: <info>  [1633014337.2818] device (E0:C3:77:CC:2F:39): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Sep 30 17:05:37 G5045 systemd[6371]: Stopped target Bluetooth.
Sep 30 17:05:37 G5045 kernel: [21750.001032] usb 2-1.3: USB disconnect, device number 58
Sep 30 17:05:37 G5045 systemd[1]: Stopped target Bluetooth.
Sep 30 17:05:37 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:05:37 G5045 kernel: [21750.224291] usb 2-1.3: new full-speed USB device number 59 using ehci-pci
Sep 30 17:05:43 G5045 kernel: [21755.481456] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.02
Sep 30 17:05:43 G5045 kernel: [21755.481476] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:05:43 G5045 NetworkManager[1212]: <info>  [1633014343.3598] manager: (E0:C3:77:CC:2F:39): new Bluetooth device (/org/freedesktop/NetworkManager/Devices/160)
Sep 30 17:05:43 G5045 NetworkManager[1212]: <info>  [1633014343.3645] device (E0:C3:77:CC:2F:39): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Sep 30 17:05:43 G5045 NetworkManager[1212]: <info>  [1633014343.4235] device (E0:C3:77:CC:2F:39): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Sep 30 17:05:43 G5045 NetworkManager[1212]: <info>  [1633014343.4618] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:05:43 G5045 NetworkManager[1212]: <info>  [1633014343.4768] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:05:43 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:05:43 G5045 systemd-udevd[185675]: hci0: Process '/usr/bin/hciconfig hci0 up' failed with exit code 1.
Sep 30 17:05:43 G5045 systemd[6371]: Reached target Bluetooth.
Sep 30 17:05:43 G5045 systemd[1]: Reached target Bluetooth.
Sep 30 17:05:44 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:44 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:44 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:44 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:44 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:44 G5045 kernel: [21756.930985] input: CORSAIR HARPOON as /devices/virtual/misc/uhid/0005:1B5E:1B1C.0013/input/input41
Sep 30 17:05:44 G5045 kernel: [21756.931465] hid-generic 0005:1B5E:1B1C.0013: input,hidraw5: BLUETOOTH HID v1.0d Mouse [CORSAIR HARPOON] on 18:cf:5e:50:20:bc
Sep 30 17:05:51 G5045 kernel: [21763.441496] usb 2-1.3: USB disconnect, device number 59
Sep 30 17:05:51 G5045 systemd[6371]: Stopped target Bluetooth.
Sep 30 17:05:51 G5045 systemd[1]: Stopped target Bluetooth.
Sep 30 17:05:51 G5045 NetworkManager[1212]: <info>  [1633014351.2100] device (E0:C3:77:CC:2F:39): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Sep 30 17:05:51 G5045 kernel: [21763.568200] usb 2-1.3: new full-speed USB device number 60 using ehci-pci
Sep 30 17:05:51 G5045 kernel: [21763.677327] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.01
Sep 30 17:05:51 G5045 kernel: [21763.677340] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:05:51 G5045 kernel: [21763.679121] usb 2-1.3: firmware: direct-loading firmware ar3k/ramps_0x31010000_40.dfu
Sep 30 17:05:51 G5045 kernel: [21763.877267] usb 2-1.3: USB disconnect, device number 60
Sep 30 17:05:51 G5045 kernel: [21764.100222] usb 2-1.3: new full-speed USB device number 61 using ehci-pci
Sep 30 17:05:51 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:05:56 G5045 kernel: [21769.309327] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.02
Sep 30 17:05:56 G5045 kernel: [21769.309348] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:05:57 G5045 NetworkManager[1212]: <info>  [1633014357.1141] manager: (E0:C3:77:CC:2F:39): new Bluetooth device (/org/freedesktop/NetworkManager/Devices/161)
Sep 30 17:05:57 G5045 NetworkManager[1212]: <info>  [1633014357.1185] device (E0:C3:77:CC:2F:39): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Sep 30 17:05:57 G5045 NetworkManager[1212]: <info>  [1633014357.1276] device (E0:C3:77:CC:2F:39): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Sep 30 17:05:57 G5045 NetworkManager[1212]: <info>  [1633014357.2785] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:05:57 G5045 NetworkManager[1212]: <info>  [1633014357.2987] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:05:57 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:05:57 G5045 systemd-udevd[186167]: hci0: Process '/usr/bin/hciconfig hci0 up' failed with exit code 1.
Sep 30 17:05:57 G5045 systemd[6371]: Reached target Bluetooth.
Sep 30 17:05:57 G5045 systemd[1]: Reached target Bluetooth.
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 bluetoothd[166557]: profiles/input/hog-lib.c:report_value_cb() bt_uhid_send: Invalid argument (22)
Sep 30 17:05:57 G5045 kernel: [21770.280931] input: CORSAIR HARPOON as /devices/virtual/misc/uhid/0005:1B5E:1B1C.0014/input/input42
Sep 30 17:05:57 G5045 kernel: [21770.281311] hid-generic 0005:1B5E:1B1C.0014: input,hidraw5: BLUETOOTH HID v1.0d Mouse [CORSAIR HARPOON] on 18:cf:5e:50:20:bc
Sep 30 17:06:02 G5045 kernel: [21774.856900] usb 2-1.3: USB disconnect, device number 61
Sep 30 17:06:02 G5045 systemd[6371]: Stopped target Bluetooth.
Sep 30 17:06:02 G5045 systemd[1]: Stopped target Bluetooth.
Sep 30 17:06:02 G5045 NetworkManager[1212]: <info>  [1633014362.6199] device (E0:C3:77:CC:2F:39): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Sep 30 17:06:02 G5045 kernel: [21774.990129] usb 2-1.3: new full-speed USB device number 62 using ehci-pci
Sep 30 17:06:02 G5045 kernel: [21775.101397] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.01
Sep 30 17:06:02 G5045 kernel: [21775.101412] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:06:02 G5045 kernel: [21775.103184] usb 2-1.3: firmware: direct-loading firmware ar3k/ramps_0x31010000_40.dfu
Sep 30 17:06:02 G5045 kernel: [21775.223354] usb 2-1.3: USB disconnect, device number 62
Sep 30 17:06:03 G5045 kernel: [21775.452102] usb 2-1.3: new full-speed USB device number 63 using ehci-pci
Sep 30 17:06:03 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:06:08 G5045 kernel: [21780.569412] usb 2-1.3: New USB device found, idVendor=0cf3, idProduct=3004, bcdDevice= 0.02
Sep 30 17:06:08 G5045 kernel: [21780.569425] usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 30 17:06:08 G5045 NetworkManager[1212]: <info>  [1633014368.3725] manager: (E0:C3:77:CC:2F:39): new Bluetooth device (/org/freedesktop/NetworkManager/Devices/162)
Sep 30 17:06:08 G5045 NetworkManager[1212]: <info>  [1633014368.3751] device (E0:C3:77:CC:2F:39): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Sep 30 17:06:08 G5045 NetworkManager[1212]: <info>  [1633014368.3801] device (E0:C3:77:CC:2F:39): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Sep 30 17:06:08 G5045 NetworkManager[1212]: <info>  [1633014368.4891] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:06:08 G5045 NetworkManager[1212]: <info>  [1633014368.4985] audit: op="statistics" arg="refresh-rate-ms" pid=7738 uid=1000 result="success"
Sep 30 17:06:08 G5045 upowerd[166548]: treating change event as add on /sys/devices/pci0000:00/0000:00:13.0/usb2/2-1/2-1.3
Sep 30 17:06:08 G5045 systemd-udevd[186636]: hci0: Process '/usr/bin/hciconfig hci0 up' failed with exit code 1.
Sep 30 17:06:08 G5045 systemd[1]: Reached target Bluetooth.
Sep 30 17:06:08 G5045 systemd[6371]: Reached target Bluetooth.

Thanks.

Stefano
#995399#10
Date:
2021-12-29 10:17:13 UTC
From:
To:
Dear Maintainer,

yesterday I switch to win10 (dual boot) and bluetooth works so isn't a
hardware problem (good new!).

Back to Debian I done new tests.

Again the bluetoothd is up when I move the mouse and goes down if not, but
I've noticed a new line in system.log

Dec 29 10:36:43 G5045 bluetoothd[1386]: src/adv_monitor.c:btd_adv_monitor_power_down() Unexpected NULL btd_adv_monitor_manager object upon power down

after that the bluetooth is definitely disable!

Thanks
#995399#15
Date:
2024-01-22 12:48:58 UTC
From:
To:
Dear Maintainer,


I have similar behavior with a bluetooth speaker instead of a mouse. In my
case, when I pair the speaker, it connects fine and stays connected. The
problem comes up as soon as I pause any audio or video. About 3 seconds
after pausing media playback, `bluetooth.service` restarts (`code=killed,
status=11/SEGV`) and the speaker disconnects.

Following are the bluetooth service logs and dmesg output around the time
where playback was paused and the speaker disconnected.