hassio-plejd: [Support] Bluetooth connectivity lost due to onWriteFailed?

Two days ago, without making any (known) changes to my Home Assistant installation nor to the Plejd Addon, I became unable to control my Plejd devices from Home Assistant. Everything still works as expected through the Plejd application on my phone.

Symptoms

In Home Assistant, if I toggle a light, the HA UI will indicate that it’s attempting to toggle the light but shortly thereafter the UI will “go back” to just showing the light being off.

I have attached a video where I show how I attempt to toggle three lights. Two of them (Spotlights and hall bv) are Plejd devices. The third one (Hall Lamp Kallax, which works as expected) is a Zigbee light.

https://youtube.com/shorts/RgFabFhBjBI

As far as I can tell, no other parts of Home Assistant are missbehaving.

System

Hardware: Raspberry Pi 4 8GB Bluetooth device: Built-in Home Assistant: 2023.8.4 Supervisor: 2023.08.3 Operating System: 10.5

The Home Assistant system was originally deployed a little bit more than a year ago. The system has been reasonably stable in the past but I have experienced similar issues with Plejd, maybe once or twice. However, the past few issues have always been resolved after a reboot.

Troubleshooting steps taken

Thusfar I have:

• Rebooted the addon
• Rebooted Home Assistant
• Rebooted the Raspberry Pi on which everything is running
• Followed the recommended “get a shell on the device and manually toggle bluetoothctl”

Observations

Looking through my Home Assistant logs for plejd-ble, I can see that something happened after 2023-09-06T15:00.

Upon closer inspection, I see that things were working as usual, until I get an onWriteFailed error (which actually seems to be a debug-message, which is weird in itself).

15:17:45.112 DBG [plejd-ble] Utebelysning entrén  (EDDA809D84A4_0) got state+dim update. S: 0, D: 0
15:18:01.362 DBG [plejd-ble] Tak spotlights  (FB7C22BB27C6_0) got state+dim update. S: 0, D: 255
15:18:04.611 DBG [plejd-ble] Plejd clock time update Wed Sep 06 2023 14:22:08 GMT+0200 (Central European Summer Time), diff -3356 seconds
15:18:04.612 WRN [plejd-ble] Plejd clock time off by more than 1 minute. Reported time: Wed Sep 06 2023 14:22:08 GMT+0200 (Central European Summer Time), diff -3356 seconds. Time will be set hourly.
15:18:15.112 DBG [plejd-ble] Hall vid entrén  (F6336380DD22_0) got state+dim update. S: 0, D: 224
15:18:25.362 DBG [plejd-ble] Fönsteruttag  (E3486B6A4232_1) got state+dim update. S: 0, D: 248
15:18:45.362 DBG [plejd-ble] onWriteFailed #1 in a row. In Progress
15:18:45.363 DBusError: In Progress
15:18:45.370 at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
15:18:45.372 at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
15:18:45.375 at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
15:18:45.378 at EventEmitter.emit (events.js:314:20)
15:18:45.380 at /plejd/node_modules/dbus-next/lib/connection.js:116:14
15:18:45.385 at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
15:18:45.386 at Socket.emit (events.js:314:20)
15:18:45.390 at emitReadable_ (_stream_readable.js:557:12)
15:18:45.393 at processTicksAndRejections (internal/process/task_queues.js:83:21)

Looking at what follows the onWriteFailed (included again for completeness) I see another two of the same error followed by a 'Not connected' writing to Plejd message.

I have removed the timestamps to make the logs easier to read. Everything happens within a minute or so.

DBG [plejd-ble] onWriteFailed #1 in a row. In Progress
DBusError: In Progress
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at Socket.emit (events.js:314:20)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
DBG [plejd-ble] onWriteFailed #2 in a row. Operation failed with ATT error: 0x0e
DBusError: Operation failed with ATT error: 0x0e
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at Socket.emit (events.js:314:20)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
ERR [plejd-ble] 'Unlikely error' (0x0e) writing to Plejd. Will retry. Operation failed with ATT error: 0x0e
DBusError: Operation failed with ATT error: 0x0e
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at Socket.emit (events.js:314:20)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
DBG [plejd-ble] onWriteFailed #3 in a row. Not connected
DBusError: Not connected
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.emit (events.js:314:20)
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
ERR [plejd-ble] 'Not connected' writing to Plejd. Plejd device is probably disconnected.
WRN [plejd-ble] Write error indicates BLE is disconnected. Retry count 3. Reconnecting...
INF [plejd-ble] Starting reconnect loop...
INF [device-comm] Bluetooth reconnecting...
INF [plejd-ble] init()
INF [plejd-ble] Reconnecting BLE...
DBG [plejd-ble] Found BLE interface 'org.bluez.Adapter1' at /org/bluez/hci0
INF [plejd-ble] BLE init done, waiting for devices.
DBG [plejd-ble] initDiscoveredPlejdDevice(). Got /org/bluez/hci0/dev_F6_33_63_80_DD_22 device
DBG [plejd-ble] Found Plejd service on /org/bluez/hci0/dev_F6_33_63_80_DD_22
DBG [plejd-ble] Inspecting /org/bluez/hci0/dev_F6_33_63_80_DD_22
DBG [plejd-ble] Discovered /org/bluez/hci0/dev_F6_33_63_80_DD_22 with rssi -85 dBm, name undefined
INF [plejd-ble] Connecting to /org/bluez/hci0/dev_F6_33_63_80_DD_22
INF [plejd-ble] Device discovery done, found 1 Plejd devices
DBusError: le-connection-abort-by-local
WRN [plejd-ble] Unable to connect.  le-connection-abort-by-local
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at Socket.emit (events.js:314:20)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)
ERR [plejd-ble] Could not connect to any Plejd device. Starting reconnect loop...
DBG [plejd-ble] Starting reconnect loop due to Could not connect to any Plejd device
INF [plejd-ble] Starting reconnect loop...
INF [device-comm] Bluetooth reconnecting...
INF [plejd-ble] init()
INF [plejd-ble] Reconnecting BLE...
DBG [plejd-ble] Found BLE interface 'org.bluez.Adapter1' at /org/bluez/hci0
INF [plejd-ble] BLE init done, waiting for devices.
DBG [plejd-ble] Starting reconnect loop due to Discovery timeout elapsed
ERR [plejd-ble] Discovery timeout elapsed, no devices found. Starting reconnect loop...
INF [plejd-ble] Starting reconnect loop...
INF [device-comm] Bluetooth reconnecting...
INF [plejd-ble] Reconnecting BLE...
INF [plejd-ble] init()
DBG [plejd-ble] Found BLE interface 'org.bluez.Adapter1' at /org/bluez/hci0
DBusError: Operation already in progress

The above then goes into “the usual” loop where it attempts to reconnect, but the addon never seem to settle in a working state.

I also looked at the logs from the perspective of a reboot of the addon. There are A LOT of rows, but I have truncated the output in a reasonable way (I hope).

2023-09-08 06:35:12 INF [plejd-mqtt] Mqtt disconnect requested. Setting all devices as unavailable in HA...
[cont-finish.d] executing container finish scripts...
[cont-finish.d] 99-message.sh: executing...
[cont-finish.d] 99-message.sh: exited 0.
[cont-finish.d] done.
[s6-finish] waiting for services.
[s6-finish] sending all processes the TERM signal.
[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 00-banner.sh: executing...
-----------------------------------------------------------
 Adds support for the Swedish home automation devices from Plejd.
 Add-on: Plejd
-----------------------------------------------------------
 Add-on version: 0.10.0
[32m You are running the latest version of this add-on.
parse error: Expected string key before ':' at line 1, column 4
[06:35:15] ERROR: Unknown HTTP error occured
 Home Assistant Core: 2023.8.4
 System:   (aarch64 / raspberrypi4-64)
 Home Assistant Supervisor: 2023.08.3
 Please, share the above information when looking for help
-----------------------------------------------------------
 or support in, e.g., GitHub, forums or the Discord chat.
[cont-init.d] 00-banner.sh: exited 0.
-----------------------------------------------------------
[cont-init.d] 01-log-level.sh: executing...
[cont-init.d] 01-log-level.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
[06:35:17] INFO:Verified permissions on startup script
[06:35:17] INFO:Starting the Plejd service...
[06:35:17] INFO:Executing startup script
[06:35:17] INFO:Running add-on
site: 'Ryd V 46',
Config: {
username: '---scrubbed---',
password: '---scrubbed---',
mqttBroker: 'mqtt://localhost',
mqttUsername: 'mqtt-plejd',
mqttPassword: '---scrubbed---',
includeRoomsAsLights: true,
preferCachedApiResponse: false,
updatePlejdClock: true,
logLevel: 'silly',
connectionTimeout: 2,
writeQueueWaitTime: 400
}
Starting Plejd addon and reading configuration...
2023-09-08 06:35:18 SLY [plejd-main] Log level set to silly
2023-09-08 06:35:18 SLY [plejd-main] Log level set to silly
2023-09-08 06:35:18INF [plejd-main] Plejd add-on, version 0.10.0
2023-09-08 06:35:18 VRB [plejd-main] Addon info: {""name"":""Plejd"",""version"":""0.10.0"",""slug"":""plejd"",""description"":""Adds support for the Swedish home automation devices from Plejd."",""url"":""https://github.com/icanos/hassio-plejd/"",""arch"":[""armhf"",""armv7"",""aarch64"",""amd64"",""i386""],""startup"":""application"",""boot"":""auto"",""host_network"":true,""host_dbus"":true,""apparmor"":false}
2023-09-08 06:35:18INF [device-comm] Starting Plejd communication handler.
2023-09-08 06:35:18INF [plejd-ble] Starting Plejd BLE Handler, resetting all device states.
2023-09-08 06:35:18INF [plejd-main] Main Plejd addon init()...
2023-09-08 06:35:18INF [plejd-api] init()
2023-09-08 06:35:18INF [plejd-api] Getting cached api response from disk
2023-09-08 06:35:18 DBG [plejd-api] Prefer cache? false
2023-09-08 06:35:18 DBG [plejd-api] Cache exists? Yes, created 2023-09-07T05:00:16.872Z
2023-09-08 06:35:18INF [plejd-api] login()
2023-09-08 06:35:18INF [plejd-api] logging into Ryd V 46
2023-09-08 06:35:18 DBG [plejd-api] sending POST to https://cloud.plejd.com/parse/login
2023-09-08 06:35:18INF [plejd-api] got session token response
2023-09-08 06:35:18INF [plejd-api] Get all Plejd sites for account...
2023-09-08 06:35:18 DBG [plejd-api] sending POST to https://cloud.plejd.com/parse/functions/getSiteList
2023-09-08 06:35:18INF [plejd-api] Got site list response with 1: Ryd V 46
2023-09-08 06:35:18 SLY [plejd-api] All sites found:
2023-09-08 06:35:18 SLY [plejd-api] [
{
""site"": {
""siteId"": ""<redacted>"",
""title"": ""Ryd V 46""
},
""plejdDevice"": [
<9 device IDs>
],
""gateway"": [],
""hasRemoteControlAccess"": false,
""sitePermission"": {
""siteId"": ""<redacted>"",
""isOwner"": true,
""isInstaller"": false,
""isUser"": false,
""locked"": false,
""hidden"": false
}
}
]
2023-09-08 06:35:18INF [plejd-api] Site found matching configuration name Ryd V 46
2023-09-08 06:35:18 SLY [plejd-api] {<redacted>}
2023-09-08 06:35:18INF [plejd-api] Get site details for <redacted>...
2023-09-08 06:35:18 DBG [plejd-api] sending POST to https://cloud.plejd.com/parse/functions/getSiteById
2023-09-08 06:35:19INF [plejd-api] Site details for site id <redacted> found
2023-09-08 06:35:19INF [plejd-api] got site details response
""site"": {
2023-09-08 06:35:19 SLY [plejd-api] {
""installers"": [
""aJcXRctXMM""
],
""title"": ""Ryd V 46"",
""siteId"": ""<redacted>"",
""createdAt"": ""2020-11-03T14:06:18.368Z"",
""version"": 499,
""updatedAt"": ""2022-08-02T04:42:12.680Z"",
""plejdMesh"": {
""__type"": ""Pointer"",
""className"": ""PlejdMesh"",
""objectId"": ""<redacted>""
},
""sunrise"": [],
""sunset"": []
},
""city"": ""<redacted>"",
""siteId"": ""<redacted>"",
""plejdMesh"": {
""plejdMeshId"": ""<redacted>"",
""meshKey"": ""<redacted>"",
""cryptoKey"": ""<redacted>"",
""createdAt"": ""2020-11-03T14:06:18.368Z"",
""updatedAt"": ""2020-11-03T14:06:18.549Z"",
""site"": {},
""ACL"": {},
""objectId"": ""<redacted>"",
""__type"": ""Object"",
""className"": ""PlejdMesh""
},
""rooms"": [
{
""siteId"": ""<redacted>"",
""roomId"": ""94d984de-77cd-48bb-be9b-09878805f0b4"",
""title"": ""Uterum"",
""category"": ""Other"",
""imageHash"": 0,
""createdAt"": ""2020-11-03T14:07:22.849Z"",
""updatedAt"": ""2020-11-05T08:51:02.387Z"",
""ACL"": {},
""objectId"": ""5BxSJnh0Vd"",
""__type"": ""Object"",
""className"": ""Room""
},
<long list of rooms>
],
""scenes"": [],
{
""devices"": [
""deviceId"": ""E99BE5855F94"",
""siteId"": ""<redacted>"",
""title"": ""Tak"",
""traits"": 11,
""hiddenFromRoomList"": false,
""roomId"": ""94d984de-77cd-48bb-be9b-09878805f0b4"",
""createdAt"": ""2020-11-03T14:08:04.763Z"",
""updatedAt"": ""2020-11-05T08:52:02.109Z"",
""hiddenFromIntegrations"": false,
""outputType"": ""LIGHT"",
""ACL"": {},
""objectId"": ""KMjcMsEmTE"",
""__type"": ""Object"",
""className"": ""Device""
},
<long list of devices>
],
<more plejd bootup stuff>
}
2023-09-08 06:35:19INF [plejd-api] Saving cached copy
2023-09-08 06:35:19INF [plejd-api] Getting devices from site details response...
2023-09-08 06:35:19INF [plejd-api] No Plejd gateway found on site
2023-09-08 06:35:19 VRB [device-registry] Added/updated output device: {""bleOutputAddress"":11,""deviceId"":""E99BE5855F94"",""dimmable"":true,""name"":""Tak"",""output"":0,""roomId"":""94d984de-77cd-48bb-be9b-09878805f0b4"",""roomName"":""Uterum"",""type"":""light"",""typeDescription"":""2-channel dimmer LED, 2*100 VA"",""typeName"":""DIM-02"",""version"":""2.4.3"",""uniqueId"":""E99BE5855F94_0""}. 1 output devices in total.
2023-09-08 06:35:19 VRB [device-registry] Added device to room 94d984de-77cd-48bb-be9b-09878805f0b4: [""E99BE5855F94_0""]
<dozens of row with the same thing>
2023-09-08 06:35:19 DBG [plejd-api] includeRoomsAsLights is set to true, adding rooms too.
2023-09-08 06:35:19 VRB [device-registry] Added/updated output device: {""bleOutputAddress"":10,""deviceId"":null,""dimmable"":true,""name"":""Uterum"",""type"":""light"",""typeDescription"":""A Plejd room"",""typeName"":""Room"",""uniqueId"":""94d984de-77cd-48bb-be9b-09878805f0b4""}. 14 output devices in total.
2023-09-08 06:35:19 VRB [device-registry] Added device to room undefined: [""94d984de-77cd-48bb-be9b-09878805f0b4""]
<a handful of rows with the same thing>
2023-09-08 06:35:19 DBG [plejd-api] includeRoomsAsLights done.
2023-09-08 06:35:19INF [plejd-mqtt] Initializing MQTT connection for Plejd addon
2023-09-08 06:35:19 VRB [plejd-ble] cleanup() - Clearing ping interval and clock update timer
2023-09-08 06:35:19 VRB [plejd-ble] Removing listeners to write events, bus events and objectManager...
2023-09-08 06:35:19INF [plejd-ble] init()
2023-09-08 06:35:19 VRB [plejd-ble] Managed paths[
""/org/bluez"",
""/org/bluez/hci0"",
""/org/bluez/hci0/dev_F6_33_63_80_DD_22""
]
2023-09-08 06:35:19 DBG [plejd-ble] Found BLE interface 'org.bluez.Adapter1' at /org/bluez/hci0
2023-09-08 06:35:19 VRB [plejd-ble] Powering on BLE adapter and waiting 5 seconds
2023-09-08 06:35:19INF [plejd-mqtt] Connected to MQTT.
2023-09-08 06:35:20 VRB [plejd-main] connected to mqtt.
2023-09-08 06:35:20INF [plejd-mqtt] Sending discovery for 17 Plejd output devices
2023-09-08 06:35:20 DBG [plejd-mqtt] Sending discovery for Tak
2023-09-08 06:35:20INF [plejd-mqtt] Discovered DIM-02 (light) named Tak (11 : E99BE5855F94_0).
<16 more send messages>
2023-09-08 06:35:20INF [plejd-mqtt] Sending discovery for 0 Plejd input devices
2023-09-08 06:35:20INF [plejd-mqtt] Sending discovery for 0 Plejd scene devices
2023-09-08 06:35:20 VRB [plejd-mqtt] Received mqtt message on homeassistant/light/plejd/E99BE5855F94_0/config
2023-09-08 06:35:20 VRB [plejd-mqtt] Getting device E99BE5855F94_0 from registry
2023-09-08 06:35:20 VRB [plejd-mqtt] Sent mqtt config command for light, Tak (E99BE5855F94_0).
2023-09-08 06:35:20 VRB [plejd-mqtt] Received mqtt message on homeassistant/light/plejd/E99BE5855F94_0/availability
2023-09-08 06:35:20 VRB [plejd-mqtt] Getting device E99BE5855F94_0 from registry
2023-09-08 06:35:20 VRB [plejd-mqtt] Sent mqtt availability command for light, Tak (E99BE5855F94_0). offline
2023-09-08 06:35:20 VRB [plejd-mqtt] Received mqtt message on homeassistant/light/plejd/E99BE5855F94_0/state
2023-09-08 06:35:20 VRB [plejd-mqtt] Getting device E99BE5855F94_0 from registry
2023-09-08 06:35:20 VRB [plejd-mqtt] Sent mqtt state command for light, Tak (E99BE5855F94_0).
2023-09-08 06:35:20 VRB [plejd-mqtt] Received mqtt message on homeassistant/light/plejd/E99BE5855F94_0/set
2023-09-08 06:35:20 VRB [plejd-mqtt] Getting device E99BE5855F94_0 from registry
2023-09-08 06:35:20 VRB [plejd-mqtt] Got mqtt SET command for light, Tak (E99BE5855F94_0): {""state"":""OFF""}
2023-09-08 06:35:20INF [device-comm] Plejd got turn off command for Tak (E99BE5855F94_0)
2023-09-08 06:35:20 DBG [device-comm] Queueing turn off E99BE5855F94_0
<very many rows of similar sort for other devices>
2023-09-08 06:35:20 VRB [plejd-mqtt] Received mqtt message on homeassistant/light/plejd/E99BE5855F94_0/config
2023-09-08 06:35:20 VRB [plejd-mqtt] Getting device E99BE5855F94_0 from registry
2023-09-08 06:35:20 VRB [plejd-mqtt] Sent mqtt config command for light, Tak (E99BE5855F94_0).
<repetition again>
2023-09-08 06:35:24 VRB [plejd-ble] Iterating 3 BLE managedObjects looking for org.bluez.Device1
2023-09-08 06:35:24 ERR [plejd-ble] Error handling /org/bluez/hci0/dev_F6_33_63_80_DD_22 interface not found in proxy object: org.bluez.Device1
Error: interface not found in proxy object: org.bluez.Device1
at ProxyObject.getInterface (/plejd/node_modules/dbus-next/lib/client/proxy-object.js:81:13)
at PlejBLEHandler._cleanExistingConnections (/plejd/PlejdBLEHandler.js:392:44)
at processTicksAndRejections (internal/process/task_queues.js:97:5)
at async PlejBLEHandler._getInterface (/plejd/PlejdBLEHandler.js:343:11)
at async PlejBLEHandler.init (/plejd/PlejdBLEHandler.js:152:5)
at async PlejdDeviceCommunication.init (/plejd/PlejdDeviceCommunication.js:72:7)
at async PlejdAddon.init (/plejd/PlejdAddon.js:157:5)
at async main (/plejd/main.js:18:5)
2023-09-08 06:35:24 VRB [plejd-ble] All active BLE device connections cleaned up.
2023-09-08 06:35:24 VRB [plejd-ble] Setting up interfacesAdded subscription and discovery filter
2023-09-08 06:35:24 VRB [plejd-ble] Got adapter undefined
2023-09-08 06:35:24 VRB [plejd-ble] Starting BLE discovery... This can take up to 180 seconds.
2023-09-08 06:35:24 VRB [plejd-ble] Started BLE discovery
2023-09-08 06:35:24INF [plejd-ble] BLE init done, waiting for devices.
2023-09-08 06:35:24INF [plejd-main] Main init done
2023-09-08 06:35:24INF [plejd-main] main() finished
2023-09-08 06:35:26 ERR [plejd-ble] Discovery timeout elapsed, no devices found. Starting reconnect loop...
2023-09-08 06:35:26 DBG [plejd-ble] Starting reconnect loop due to Discovery timeout elapsed
2023-09-08 06:35:26INF [plejd-ble] Starting reconnect loop...
2023-09-08 06:35:26 VRB [plejd-ble] Starting internal reconnect loop...
2023-09-08 06:35:26 VRB [plejd-ble] Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...
2023-09-08 06:35:26 VRB [plejd-ble] cleanup() - Clearing ping interval and clock update timer
2023-09-08 06:35:26 VRB [plejd-ble] Removing listeners to write events, bus events and objectManager...
2023-09-08 06:35:26 VRB [plejd-ble] Reconnect attempt 1 in a row. Will power cycle every 10th time.
2023-09-08 06:35:26INF [device-comm] Bluetooth reconnecting...
2023-09-08 06:35:26 VRB [device-comm] Stopping writeQueue loop until connection is established. Write queue length: 17
2023-09-08 06:35:32INF [plejd-ble] init()
2023-09-08 06:35:31INF [plejd-ble] Reconnecting BLE...
2023-09-08 06:35:32 VRB [plejd-ble] Managed paths[
""/org/bluez"",
""/org/bluez/hci0"",
""/org/bluez/hci0/dev_E9_9B_E5_85_5F_94""
]
2023-09-08 06:35:32 DBG [plejd-ble] Found BLE interface 'org.bluez.Adapter1' at /org/bluez/hci0
2023-09-08 06:35:32 VRB [plejd-ble] Powering on BLE adapter and waiting 5 seconds
2023-09-08 06:35:37 VRB [plejd-ble] Found /org/bluez/hci0/dev_E9_9B_E5_85_5F_94
2023-09-08 06:35:37 VRB [plejd-ble] Iterating 3 BLE managedObjects looking for org.bluez.Device1
2023-09-08 06:35:37 VRB [plejd-ble] Removing /org/bluez/hci0/dev_E9_9B_E5_85_5F_94 from adapter.
2023-09-08 06:35:37 VRB [plejd-ble] All active BLE device connections cleaned up.
2023-09-08 06:35:37 VRB [plejd-ble] Got adapter undefined
2023-09-08 06:35:37 VRB [plejd-ble] Setting up interfacesAdded subscription and discovery filter
2023-09-08 06:35:37 VRB [plejd-ble] Starting BLE discovery... This can take up to 180 seconds.
2023-09-08 06:35:37 ERR [plejd-ble] Failed to start discovery. Operation already in progress
at _methodReturnHandlers.<computed> (/plejd/node_modules/dbus-next/lib/bus.js:343:27)
DBusError: Operation already in progress
at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11)
at EventEmitter.<anonymous> (/plejd/node_modules/dbus-next/lib/bus.js:151:9)
at EventEmitter.emit (events.js:314:20)
at /plejd/node_modules/dbus-next/lib/connection.js:116:14
at Socket.<anonymous> (/plejd/node_modules/dbus-next/lib/message.js:63:9)
at Socket.emit (events.js:314:20)
at emitReadable_ (_stream_readable.js:557:12)
at processTicksAndRejections (internal/process/task_queues.js:83:21)

My guess would be that there’s an hardware issue, but it seems so weird that a bluetooth chip would just stop working. Maybe it’s not so far fetched?

Help needed

Any assistance in troubleshooting this further is greately appreciated.