Restart Bluetooth interface every 30 seconds can break Bluetooth controller driver
archekb opened this issue · 3 comments
archekb commented
When all Bluetooth devices (from config) are offline, daemon will restart Bluetooth interface every 30 seconds. It can break Bluetooth controller driver (in my case Atheros AR3012 Bluetooth 4.0 Adapter).
root@ble2mqtt:/# rfkill list
0: hci0: Bluetooth
Soft blocked: no
Hard blocked: no
1: phy0: Wireless LAN
Soft blocked: no
Hard blocked: no
root@ble2mqtt:/# hciconfig hci0 up
Can't init device hci0: Connection timed out (110)
root@ble2mqtt:/# hciconfig
hci0: Type: Primary Bus: USB
BD Address: 24:0A:64:C8:36:64 ACL MTU: 1022:8 SCO MTU: 183:5
DOWN INIT RUNNING
RX bytes:19840 acl:0 sco:0 events:668 errors:0
TX bytes:2289 acl:0 sco:0 commands:726 errors:7
root@ble2mqtt:/# hciconfig hci0 up
Can't init device hci0: Connection timed out (110)
After that for UP Bluetooth interface I should remount driver, all another ways (host reboot too) have no effect.
rmmod ath3k
rmmod btusb
modprobe btusb
I think, we need some another way for check Bluetooth adapter status (online or offline) and restart interface only when it did not works.
syslog (GMT)
May 22 13:39:03 hsrv systemd[1]: Stopped target Bluetooth.
May 22 13:39:03 hsrv kernel: [ 8620.369121] usb 1-9: new full-speed USB device number 71 using xhci_hcd
May 22 13:39:04 hsrv kernel: [ 8620.519573] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.01
May 22 13:39:04 hsrv kernel: [ 8620.519580] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:39:04 hsrv kernel: [ 8620.519585] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:39:04 hsrv kernel: [ 8620.519588] usb 1-9: Manufacturer: Atheros Communications
May 22 13:39:04 hsrv kernel: [ 8620.519591] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:39:04 hsrv kernel: [ 8620.569272] usb 1-9: USB disconnect, device number 71
May 22 13:39:04 hsrv kernel: [ 8620.877300] usb 1-9: new full-speed USB device number 72 using xhci_hcd
May 22 13:39:08 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:39:09 hsrv kernel: [ 8626.191998] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.02
May 22 13:39:09 hsrv kernel: [ 8626.192004] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:39:09 hsrv kernel: [ 8626.192009] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:39:09 hsrv kernel: [ 8626.192013] usb 1-9: Manufacturer: Atheros Communications
May 22 13:39:09 hsrv kernel: [ 8626.192016] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:39:09 hsrv systemd[1]: Starting Load/Save RF Kill Switch Status...
May 22 13:39:09 hsrv systemd[1]: Reached target Bluetooth.
May 22 13:39:09 hsrv systemd[3763]: Reached target Bluetooth.
May 22 13:39:09 hsrv systemd[1]: Started Load/Save RF Kill Switch Status.
May 22 13:39:14 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:39:20 hsrv kernel: [ 8637.427978] usb 1-9: USB disconnect, device number 72
May 22 13:39:20 hsrv systemd[1]: Starting Load/Save RF Kill Switch Status...
May 22 13:39:20 hsrv systemd[3763]: Stopped target Bluetooth.
May 22 13:39:20 hsrv systemd[1]: Stopped target Bluetooth.
May 22 13:39:20 hsrv systemd[1]: Started Load/Save RF Kill Switch Status.
May 22 13:39:21 hsrv kernel: [ 8637.773559] usb 1-9: new full-speed USB device number 73 using xhci_hcd
May 22 13:39:21 hsrv kernel: [ 8637.924056] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.01
May 22 13:39:21 hsrv kernel: [ 8637.924063] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:39:21 hsrv kernel: [ 8637.924068] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:39:21 hsrv kernel: [ 8637.924071] usb 1-9: Manufacturer: Atheros Communications
May 22 13:39:21 hsrv kernel: [ 8637.924074] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:39:21 hsrv kernel: [ 8637.970042] usb 1-9: USB disconnect, device number 73
May 22 13:39:21 hsrv kernel: [ 8638.277737] usb 1-9: new full-speed USB device number 74 using xhci_hcd
May 22 13:39:26 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:39:27 hsrv kernel: [ 8643.600443] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.02
May 22 13:39:27 hsrv kernel: [ 8643.600451] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:39:27 hsrv kernel: [ 8643.600456] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:39:27 hsrv kernel: [ 8643.600460] usb 1-9: Manufacturer: Atheros Communications
May 22 13:39:27 hsrv kernel: [ 8643.600463] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:39:27 hsrv systemd[1]: Starting Load/Save RF Kill Switch Status...
May 22 13:39:27 hsrv systemd[3763]: Reached target Bluetooth.
May 22 13:39:27 hsrv systemd[1]: Reached target Bluetooth.
May 22 13:39:27 hsrv systemd[1]: Started Load/Save RF Kill Switch Status.
May 22 13:39:32 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:40:30 hsrv kernel: [ 8707.357930] usb 1-9: USB disconnect, device number 74
May 22 13:40:30 hsrv systemd[1]: Starting Load/Save RF Kill Switch Status...
May 22 13:40:30 hsrv systemd[1]: Started Load/Save RF Kill Switch Status.
May 22 13:40:30 hsrv systemd[3763]: Stopped target Bluetooth.
May 22 13:40:30 hsrv systemd[1]: Stopped target Bluetooth.
May 22 13:40:31 hsrv kernel: [ 8707.703253] usb 1-9: new full-speed USB device number 75 using xhci_hcd
May 22 13:40:31 hsrv kernel: [ 8707.853399] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.01
May 22 13:40:31 hsrv kernel: [ 8707.853406] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:40:31 hsrv kernel: [ 8707.853410] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:40:31 hsrv kernel: [ 8707.853414] usb 1-9: Manufacturer: Atheros Communications
May 22 13:40:31 hsrv kernel: [ 8707.853417] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:40:31 hsrv kernel: [ 8707.903413] usb 1-9: USB disconnect, device number 75
May 22 13:40:31 hsrv kernel: [ 8708.211373] usb 1-9: new full-speed USB device number 76 using xhci_hcd
May 22 13:40:35 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:40:37 hsrv kernel: [ 8713.490073] usb 1-9: New USB device found, idVendor=13d3, idProduct=3362, bcdDevice= 0.02
May 22 13:40:37 hsrv kernel: [ 8713.490082] usb 1-9: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 22 13:40:37 hsrv kernel: [ 8713.490086] usb 1-9: Product: Bluetooth USB Host Controller
May 22 13:40:37 hsrv kernel: [ 8713.490091] usb 1-9: Manufacturer: Atheros Communications
May 22 13:40:37 hsrv kernel: [ 8713.490094] usb 1-9: SerialNumber: Alaska Day 2006
May 22 13:40:37 hsrv systemd[1]: Starting Load/Save RF Kill Switch Status...
May 22 13:40:37 hsrv systemd[1]: Reached target Bluetooth.
May 22 13:40:37 hsrv systemd[3763]: Reached target Bluetooth.
May 22 13:40:37 hsrv systemd[1]: Started Load/Save RF Kill Switch Status.
May 22 13:40:42 hsrv systemd[1]: systemd-rfkill.service: Succeeded.
May 22 13:41:36 hsrv kernel: [ 8772.637013] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:36 hsrv kernel: [ 8772.637019] Bluetooth: hci0: failed to restart LE scan: status 31
May 22 13:41:38 hsrv kernel: [ 8774.653019] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:38 hsrv kernel: [ 8774.653053] Bluetooth: hci0: failed to restart LE scan: status 31
May 22 13:41:40 hsrv kernel: [ 8776.669118] Bluetooth: hci0: failed to restart LE scan: status 31
May 22 13:41:40 hsrv kernel: [ 8776.669125] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:42 hsrv kernel: [ 8778.685118] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:44 hsrv kernel: [ 8780.701257] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:46 hsrv kernel: [ 8782.717292] Bluetooth: hci0: command 0x200c tx timeout
May 22 13:41:54 hsrv kernel: [ 8790.653569] usb 1-9: Failed to access otp area (-110)
May 22 13:41:59 hsrv kernel: [ 8795.773763] usb 1-9: Failed to access otp area (-110)
May 22 13:42:43 hsrv kernel: [ 8840.447153] usb 1-9: reset full-speed USB device number 76 using xhci_hcd
May 22 13:42:46 hsrv kernel: [ 8843.134868] Bluetooth: hci0: urb 000000003633bcb9 failed to resubmit (113)
May 22 13:42:57 hsrv kernel: [ 8853.471305] Bluetooth: hci0: urb 00000000cfb066d2 failed to resubmit (113)
May 22 13:43:17 hsrv kernel: [ 8873.791481] Bluetooth: hci0: urb 0000000077edb743 failed to resubmit (113)
May 22 13:43:24 hsrv kernel: [ 8880.863918] Bluetooth: hci0: urb 0000000031c5bcc1 failed to resubmit (113)
May 22 13:44:17 hsrv kernel: [ 8933.576995] Bluetooth: hci0: urb 000000000f4b34e0 failed to resubmit (113)
May 22 13:44:28 hsrv kernel: [ 8944.497450] Bluetooth: hci0: urb 00000000ea3428b7 failed to resubmit (113)
May 22 13:44:44 hsrv kernel: [ 8961.029644] Bluetooth: hci0: urb 0000000077edb743 failed to resubmit (113)
May 22 13:44:54 hsrv kernel: [ 8971.218091] Bluetooth: hci0: urb 000000000626774a failed to resubmit (113)
May 22 13:45:16 hsrv kernel: [ 8992.502451] Bluetooth: hci0: urb 0000000045317dab failed to resubmit (113)
May 22 13:45:26 hsrv kernel: [ 9003.354588] Bluetooth: hci0: urb 000000005b23099b failed to resubmit (113)
May 22 13:45:47 hsrv kernel: [ 9023.895061] Bluetooth: hci0: urb 000000006e571a11 failed to resubmit (113)
May 22 13:45:57 hsrv kernel: [ 9034.203398] Bluetooth: hci0: urb 000000000f4b34e0 failed to resubmit (113)
May 22 13:46:42 hsrv kernel: [ 9078.720428] Bluetooth: hci0: urb 000000008087d9a2 failed to resubmit (113)
ble2mqtt (GMT+5)
ble2mqtt_1 | Starting system message bus: dbus.
ble2mqtt_1 | 2022-05-22 17:10:50 INFO: Starting BLE2MQTT version 0.1.1
ble2mqtt_1 | 2022-05-22 17:10:50 INFO: Connected to 192.168.55.10
ble2mqtt_1 | 2022-05-22 17:10:52 INFO: Connected to 02:F6:21:7E:10:96
ble2mqtt_1 | 2022-05-22 17:10:53 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'closed', 'position': 100}}
ble2mqtt_1 | 2022-05-22 17:11:02 ERROR: [Blind_AM43_0209db993941] connection problem, attempts=1
ble2mqtt_1 | 2022-05-22 17:12:05 INFO: Connected to 02:09:DB:99:39:41
ble2mqtt_1 | 2022-05-22 17:12:05 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'closed', 'position': 100}}
ble2mqtt_1 | 2022-05-22 17:14:06 INFO: [Blind_AM43_0209db993941] set mode cover to "CLOSE"
ble2mqtt_1 | 2022-05-22 17:14:06 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'closing', 'position': 100}}
ble2mqtt_1 | 2022-05-22 17:14:06 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'closing', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:07 INFO: [Blind_AM43_02f6217e1096] set mode cover to "CLOSE"
ble2mqtt_1 | 2022-05-22 17:14:07 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'closing', 'position': 100}}
ble2mqtt_1 | 2022-05-22 17:14:07 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'closing', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:10 INFO: [Blind_AM43_0209db993941] set mode cover to "STOP"
ble2mqtt_1 | 2022-05-22 17:14:11 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'stopped', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:11 INFO: [Blind_AM43_02f6217e1096] set mode cover to "STOP"
ble2mqtt_1 | 2022-05-22 17:14:11 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'stopped', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:12 INFO: [Blind_AM43_0209db993941] set mode cover to "OPEN"
ble2mqtt_1 | 2022-05-22 17:14:12 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'opening', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:12 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'opening', 'position': 81}}
ble2mqtt_1 | 2022-05-22 17:14:13 INFO: [Blind_AM43_02f6217e1096] set mode cover to "OPEN"
ble2mqtt_1 | 2022-05-22 17:14:13 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'opening', 'position': 99}}
ble2mqtt_1 | 2022-05-22 17:14:14 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'opening', 'position': 82}}
ble2mqtt_1 | 2022-05-22 17:14:18 INFO: [Blind_AM43_0209db993941] Maximum position reached. Set to OPEN
ble2mqtt_1 | 2022-05-22 17:14:18 INFO: [Blind_AM43_0209db993941] send state={'linkquality': 79, 'battery': 96, 'illuminance': 0.0, 'cover': {'state': 'open', 'position': 100}}
ble2mqtt_1 | 2022-05-22 17:14:19 INFO: [Blind_AM43_02f6217e1096] Maximum position reached. Set to OPEN
ble2mqtt_1 | 2022-05-22 17:14:19 INFO: [Blind_AM43_02f6217e1096] send state={'linkquality': 87, 'battery': 94, 'illuminance': 0.0, 'cover': {'state': 'open', 'position': 100}}
// devices are turned off
ble2mqtt_1 | 2022-05-22 17:15:43 WARNING: Error while connecting to Blind_AM43_02f6217e1096, Device with address 02:F6:21:7E:10:96 was not found. BleakError('Device with address 02:F6:21:7E:10:96 was not found.'), attempts=1
ble2mqtt_1 | 2022-05-22 17:15:45 ERROR: [Blind_AM43_0209db993941] connection problem, attempts=1
ble2mqtt_1 | 2022-05-22 17:16:45 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.UnknownObject] Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=1
ble2mqtt_1 | 2022-05-22 17:16:50 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.Failed] No discovery started BleakDBusError('org.bluez.Error.Failed', 'No discovery started'), failure_count=1
ble2mqtt_1 | 2022-05-22 17:17:50 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.freedesktop.DBus.Error.UnknownObject] Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=2
ble2mqtt_1 | 2022-05-22 17:17:52 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.bluez.Error.Failed] No discovery started BleakDBusError('org.bluez.Error.Failed', 'No discovery started'), failure_count=2
ble2mqtt_1 | 2022-05-22 17:18:59 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.bluez.Error.Failed] No discovery started BleakDBusError('org.bluez.Error.Failed', 'No discovery started'), failure_count=3
ble2mqtt_1 | 2022-05-22 17:18:59 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.Failed] No discovery started BleakDBusError('org.bluez.Error.Failed', 'No discovery started'), failure_count=3
ble2mqtt_1 | 2022-05-22 17:20:10 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.freedesktop.DBus.Error.UnknownObject] Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=4
ble2mqtt_1 | 2022-05-22 17:20:11 ERROR: [Blind_AM43_0209db993941] connection problem, attempts=2
ble2mqtt_1 | 2022-05-22 17:21:20 WARNING: Error while connecting to Blind_AM43_02f6217e1096, Device with address 02:F6:21:7E:10:96 was not found. BleakError('Device with address 02:F6:21:7E:10:96 was not found.'), attempts=2
ble2mqtt_1 | 2022-05-22 17:21:21 WARNING: Error while connecting to Blind_AM43_0209db993941, Device with address 02:09:DB:99:39:41 was not found. BleakError('Device with address 02:09:DB:99:39:41 was not found.'), attempts=3
ble2mqtt_1 | 2022-05-22 17:22:21 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.UnknownObject] Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "SetDiscoveryFilter" with signature "a{sv}" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=4
ble2mqtt_1 | 2022-05-22 17:22:28 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.Failed] No discovery started BleakDBusError('org.bluez.Error.Failed', 'No discovery started'), failure_count=5
ble2mqtt_1 | 2022-05-22 17:22:28 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 17:22:37 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 17:23:32 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.UnknownObject] Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=5
ble2mqtt_1 | 2022-05-22 17:23:32 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Can't get device info: No such device
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 17:23:41 WARNING: Restarting bluetoothd finished
// and now adapter will break
ble2mqtt_1 | 2022-05-22 18:39:05 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Can't get device info: No such device
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 18:39:15 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 18:39:25 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.UnknownObject] Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=1
ble2mqtt_1 | 2022-05-22 18:40:26 WARNING: Error while connecting to Blind_AM43_02f6217e1096, Device with address 02:F6:21:7E:10:96 was not found. BleakError('Device with address 02:F6:21:7E:10:96 was not found.'), attempts=14
ble2mqtt_1 | 2022-05-22 18:40:36 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.UnknownObject] Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn't exist
ble2mqtt_1 | BleakDBusError('org.freedesktop.DBus.Error.UnknownObject', 'Method "StopDiscovery" with signature "" on interface "org.bluez.Adapter1" doesn\'t exist\n'), failure_count=2
ble2mqtt_1 | 2022-05-22 18:41:36 WARNING: Error while connecting to Blind_AM43_02f6217e1096, Device with address 02:F6:21:7E:10:96 was not found. BleakError('Device with address 02:F6:21:7E:10:96 was not found.'), attempts=15
ble2mqtt_1 | 2022-05-22 18:41:46 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | Can't init device hci0: Input/output error (5)
ble2mqtt_1 | 2022-05-22 18:42:04 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 18:42:07 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.bluez.Error.InProgress] Operation already in progress BleakDBusError('org.bluez.Error.InProgress', 'Operation already in progress'), failure_count=3
ble2mqtt_1 | 2022-05-22 18:42:36 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
ble2mqtt_1 | 2022-05-22 18:43:09 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 18:43:09 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 18:43:12 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.NotReady] Resource Not Ready BleakDBusError('org.bluez.Error.NotReady', 'Resource Not Ready'), failure_count=1
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
ble2mqtt_1 | 2022-05-22 18:43:37 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 18:43:40 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.bluez.Error.NotReady] Resource Not Ready BleakDBusError('org.bluez.Error.NotReady', 'Resource Not Ready'), failure_count=4
ble2mqtt_1 | 2022-05-22 18:44:12 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
ble2mqtt_1 | 2022-05-22 18:44:39 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 18:44:40 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 18:44:42 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.NotReady] Resource Not Ready BleakDBusError('org.bluez.Error.NotReady', 'Resource Not Ready'), failure_count=2
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
...
ble2mqtt_1 | 2022-05-22 20:27:30 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 20:27:33 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.bluez.Error.NotReady] Resource Not Ready BleakDBusError('org.bluez.Error.NotReady', 'Resource Not Ready'), failure_count=4
ble2mqtt_1 | 2022-05-22 20:28:02 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
ble2mqtt_1 | 2022-05-22 20:28:29 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 20:28:32 WARNING: Error while connecting to Blind_AM43_02f6217e1096, [org.bluez.Error.NotReady] Resource Not Ready BleakDBusError('org.bluez.Error.NotReady', 'Resource Not Ready'), failure_count=2
ble2mqtt_1 | 2022-05-22 20:28:33 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | Can't init device hci0: Connection timed out (110)
ble2mqtt_1 | 2022-05-22 20:29:00 WARNING: Restarting bluetoothd finished
ble2mqtt_1 | 2022-05-22 20:29:03 WARNING: Error while connecting to Blind_AM43_0209db993941, [org.freedesktop.DBus.Error.AccessDenied] Client tried to send a message other than Hello without being registered BleakDBusError('org.freedesktop.DBus.Error.AccessDenied', 'Client tried to send a message other than Hello without being registered'), failure_count=5
ble2mqtt_1 | 2022-05-22 20:29:03 WARNING: Restarting bluetoothd...
ble2mqtt_1 | Stopping bluetooth: /usr/sbin/bluetoothd.
ble2mqtt_1 | Starting bluetooth: bluetoothd.
ble2mqtt_1 | 2022-05-22 20:29:16 ERROR: Caught exception: {'message': 'Future exception was never retrieved', 'exception': EOFError(), 'future': <Future finished exception=EOFError()>}
ble2mqtt_1 | 2022-05-22 20:29:16 ERROR: Future exception was never retrieved
ble2mqtt_1 | future: <Future finished exception=EOFError()>
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/dbus_next/aio/message_bus.py", line 365, in _message_reader
ble2mqtt_1 | if self._unmarshaller.unmarshall():
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/dbus_next/_private/unmarshaller.py", line 304, in unmarshall
ble2mqtt_1 | self._unmarshall()
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/dbus_next/_private/unmarshaller.py", line 243, in _unmarshall
ble2mqtt_1 | self.read(16, prefetch=True)
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/dbus_next/_private/unmarshaller.py", line 91, in read
ble2mqtt_1 | raise EOFError()
ble2mqtt_1 | EOFError
ble2mqtt_1 | 2022-05-22 20:29:16 INFO: Shutting down...
ble2mqtt_1 | 2022-05-22 20:29:16 INFO: Closing ble2mqtt service
ble2mqtt_1 | 2022-05-22 20:29:16 INFO: Cancelling 6 outstanding tasks
ble2mqtt_1 | 2022-05-22 20:29:16 ERROR: Unexpected exception while cancelling tasks! <Task finished name='Task-2' coro=<Ble2Mqtt._connect_forever() done, defined at /root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py:956> exception=ConnectionClosedError()>
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 960, in _connect_forever
ble2mqtt_1 | mqtt_connection = await self._mqtt_client.connect(
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/aio_mqtt/client.py", line 204, in connect
ble2mqtt_1 | self._reader, self._writer = await aio.open_connection(
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/streams.py", line 52, in open_connection
ble2mqtt_1 | transport, _ = await loop.create_connection(
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1050, in create_connection
ble2mqtt_1 | sock = await self._connect_sock(
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/base_events.py", line 961, in _connect_sock
ble2mqtt_1 | await self.sock_connect(sock, address)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 499, in sock_connect
ble2mqtt_1 | return await fut
ble2mqtt_1 | asyncio.exceptions.CancelledError
ble2mqtt_1 |
ble2mqtt_1 | During handling of the above exception, another exception occurred:
ble2mqtt_1 |
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 59, in cancel_tasks
ble2mqtt_1 | await t
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 984, in _connect_forever
ble2mqtt_1 | await self._mqtt_client.publish(
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/aio_mqtt/client.py", line 289, in publish
ble2mqtt_1 | self._raise_if_not_connected()
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/aio_mqtt/client.py", line 354, in _raise_if_not_connected
ble2mqtt_1 | raise ConnectionClosedError()
ble2mqtt_1 | aio_mqtt.exceptions.ConnectionClosedError
ble2mqtt_1 | 2022-05-22 20:29:16 ERROR: Task raises exception while cancelling parent coroutine that waits for it <Task finished name='Task-2' coro=<Ble2Mqtt._connect_forever() done, defined at /root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py:956> exception=ConnectionClosedError()>
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 73, in run_tasks_and_cancel_on_first_return
ble2mqtt_1 | done, pending = await aio.wait(tasks, return_when=return_when)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/tasks.py", line 413, in wait
ble2mqtt_1 | return await _wait(fs, timeout, return_when, loop)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/tasks.py", line 525, in _wait
ble2mqtt_1 | await waiter
ble2mqtt_1 | asyncio.exceptions.CancelledError
ble2mqtt_1 |
ble2mqtt_1 | During handling of the above exception, another exception occurred:
ble2mqtt_1 |
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 82, in run_tasks_and_cancel_on_first_return
ble2mqtt_1 | t.result()
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 59, in cancel_tasks
ble2mqtt_1 | await t
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 984, in _connect_forever
ble2mqtt_1 | await self._mqtt_client.publish(
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/aio_mqtt/client.py", line 289, in publish
ble2mqtt_1 | self._raise_if_not_connected()
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/aio_mqtt/client.py", line 354, in _raise_if_not_connected
ble2mqtt_1 | raise ConnectionClosedError()
ble2mqtt_1 | aio_mqtt.exceptions.ConnectionClosedError
ble2mqtt_1 | 2022-05-22 20:29:16 WARNING: Error on MQTT disconnecting: ConnectionClosedError()
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/__main__.py", line 108, in amain
ble2mqtt_1 | await service.start()
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 762, in start
ble2mqtt_1 | result = await run_tasks_and_cancel_on_first_return(
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/ble2mqtt.py", line 73, in run_tasks_and_cancel_on_first_return
ble2mqtt_1 | done, pending = await aio.wait(tasks, return_when=return_when)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/tasks.py", line 413, in wait
ble2mqtt_1 | return await _wait(fs, timeout, return_when, loop)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/tasks.py", line 525, in _wait
ble2mqtt_1 | await waiter
ble2mqtt_1 | asyncio.exceptions.CancelledError
ble2mqtt_1 |
ble2mqtt_1 | During handling of the above exception, another exception occurred:
ble2mqtt_1 |
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/runners.py", line 44, in run
ble2mqtt_1 | return loop.run_until_complete(main)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/base_events.py", line 647, in run_until_complete
ble2mqtt_1 | return future.result()
ble2mqtt_1 | asyncio.exceptions.CancelledError
ble2mqtt_1 |
ble2mqtt_1 | During handling of the above exception, another exception occurred:
ble2mqtt_1 |
ble2mqtt_1 | Traceback (most recent call last):
ble2mqtt_1 | File "/root/.local/bin/ble2mqtt", line 8, in <module>
ble2mqtt_1 | sys.exit(main())
ble2mqtt_1 | File "/root/.local/lib/python3.9/site-packages/ble2mqtt/__main__.py", line 140, in main
ble2mqtt_1 | aio.run(amain(config), debug=(config['log_level'].upper() == 'DEBUG'))
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/runners.py", line 47, in run
ble2mqtt_1 | _cancel_all_tasks(loop)
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/runners.py", line 63, in _cancel_all_tasks
ble2mqtt_1 | loop.run_until_complete(
ble2mqtt_1 | File "/usr/local/lib/python3.9/asyncio/base_events.py", line 645, in run_until_complete
ble2mqtt_1 | raise RuntimeError('Event loop stopped before Future completed.')
ble2mqtt_1 | RuntimeError: Event loop stopped before Future completed.
archekb commented
I was wrong.
This problem actual not for all Bluetooth adapters, my Atheros AR5B225 AzureWave AW-NB097H have this problem, but another my mini pc with integrated Intel Bluetooth adapter have no any probems.
I think problem with bad driver for Atheros.
devbis commented
Can you look for an appropriate solution for Atheros? Current restarting on errors works well for integrated Realtek drivers which are also poorly written, but it is the solution for this case.
archekb commented
I'm think this problem specifiс for AR5B225 (SerialNumber: Alaska Day 2006) and driver ath3k.
usb-devices | awk '/0489/' RS=
T: Bus=01 Lev=02 Prnt=02 Port=00 Cnt=01 Dev#= 3 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=e0(wlcon) Sub=01 Prot=01 MxPS=64 #Cfgs= 1
P: Vendor=0489 ProdID=e04a Rev=00.01
S: Manufacturer=Atheros Communications
S: Product=Bluetooth USB Host Controller
S: SerialNumber=Alaska Day 2006
C: #Ifs= 2 Cfg#= 1 Atr=e0 MxPwr=100mA
I: If#= 0 Alt= 0 #EPs= 3 Cls=e0(wlcon) Sub=01 Prot=01 Driver=(none)
I: If#= 1 Alt= 0 #EPs= 2 Cls=e0(wlcon) Sub=01 Prot=01 Driver=(none)
Today I buy Intel Centrino Wireless-N 2230 for 3$ and now all is works fine.