icanos / hassio-plejd

Hass.io add-on for Plejd home automation devices
Apache License 2.0
126 stars 36 forks source link

[Support] Bluetooth connectivity lost due to onWriteFailed? #286

Open ErikThorsell opened 1 year ago

ErikThorsell commented 1 year ago

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:

Observations

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

image

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.

ErikThorsell commented 1 year ago

An acquaintance mentioned that:

Operation failed with ATT error: 0x0e

is called GATT_ERR_UNLIKELY and could be the consequence of "sending data too fast".

I don't know if this information is helpful, but I figured I'd add it.

SweVictor commented 1 year ago

Hardware issues are always very tricky and not much we can do from the Addon, unfortunately.

I suppose the retry loop was "never-ending" in both cases? It goes through a couple of different state, in the end after 100 (I think) retries, it tries to power toggle the BLE adapter. In my system, those changes (probably versions 0.8 or 0.9) made a huge change in the resiliency of the addon.

Apart from that (and depending on your setup) you could try changing the timeouts in the settings: image

Those will affect how "fast" we deem things as non-functional.

/Victor

ErikThorsell commented 1 year ago

I understand that the add-on cannot take height for hardware issues, but I find it very peculiar that this error appeared out of nowhere.

I suppose the retry loop was "never-ending" in both cases?

Yes. The power toggling happens after 10 retries.

The configuration was set to 2 and 400 respectively. I have changed to 10 / 400 and will see if I experience a difference.

ErikThorsell commented 1 year ago

I made the change above and started the plugin (I turned it off after creating my issue) and it worked!

But I still had logLevel set to silly so I modified the logLevel and pressed Save (which caused a restart of the add-on).

This caused me to go back into the loop behavior...

I then turned off the add-on and let it be for a couple of minutes, before turning it on again.

Now it seems to work again.

sliter mitt hår

This might be the start of my RPi going into retirement. As a fellow swede could you recommend a good Bluetooth USB-dongel that is available on our market?

piemar commented 1 year ago

@ErikThorsell I am a swede and am using this, as the internal one was not was not stable.

https://www.kjell.com/se/produkter/mobilt/bluetooth/bluetooth-adaptrar/bluetooth-usb-adaptrar/asus-bt500-bluetooth-adapter-p62949

Another option is the below, as its recommended and tested according to the add on creator.

https://www.kjell.com/se/produkter/mobilt/bluetooth/bluetooth-adaptrar/bluetooth-usb-adaptrar/asus-bt400-bluetooth-adapter-p69885

Mats1717 commented 1 year ago

I put a Plejd smartplugg next to RPi and used 2 and 400 and now I have a stable connection. With the smartplug with 10 and 400 is was reconecting all the time as before.

ErikThorsell commented 1 year ago

I did not mention this in my original post, because I thought it was unrelated, but I had issues updating HA from 2023.8.4 to 2023.9.0 -> https://github.com/home-assistant/core/issues/99909.

2023.9.1 was released yesterday and I was able to update from 2023.8.4 to 2023.9.1 without any issues. I have not had any Plejd-issues since I updated this morning.

Will keep you posted.

ErikThorsell commented 1 year ago

Updated to 2023.9.2 same day as it was made available. After three days, my bluetooth issues reappeared. I will consider reverting to 2023.9.1 tomorrow.

d96moe commented 1 year ago

Plejd has been working like a charm for a very long time. One hour ago I updated to the latest hassio.os, and now I seem to have the same issue☹️ I usually always update both the os and the core when updates are available (running on pi4 with internal bt)

ErikThorsell commented 1 year ago

Updated to 2023.10.0 (OS 10.5) and it has been working for three days now.

Thank you for your update @d96moe, I'd urge you to have a look at: https://github.com/home-assistant/core/issues/99909 and see if you have the same issues.

TorulfDanielsson commented 1 year ago

After updating to OS 11.0 I seem to be in the same situation. Has been working without problems from a very long time. Running on Intel NUC with Intel wifi/Bluetooth.

Home Assistant 2023.10.3 Supervisor 2023.10.0 Operating System 11.0

Mats1717 commented 1 year ago

Not working for me, reconnects every 2 minuts. Has a plejd 1 meter from HA on a RPI. Had it working 4-5 weeks ago. Tried separate bluetooth USB dongle with sama problem. se logs below

2023-10-14 08:11:33 INF [plejd-ble] BLE Connected to Plejd Smartplugg 1 2023-10-14 08:11:33 INF [plejd-ble] Plejd clock updates disabled in configuration. 2023-10-14 08:11:33 INF [plejd-ble] startPing() 2023-10-14 08:11:33 INF [device-comm] Bluetooth connected. Plejd BLE up and running! 2023-10-14 08:11:33 INF [device-comm] startWriteQueue() 2023-10-14 08:12:54 WRN [plejd-ble] Write error indicates BLE is disconnected. Retry count 5. Reconnecting... 2023-10-14 08:12:54 INF [plejd-ble] Starting reconnect loop... 2023-10-14 08:12:54 INF [device-comm] Bluetooth reconnecting... 2023-10-14 08:12:59 INF [plejd-ble] Reconnecting BLE... 2023-10-14 08:12:59 INF [plejd-ble] init() 2023-10-14 08:13:04 INF [plejd-ble] disconnecting /org/bluez/hci0/dev_CC_54_0E_CD_B2_40. This can take up to 180 seconds 2023-10-14 08:13:07 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. (/plejd/node_modules/dbus-next/lib/bus.js:343:27) at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11) at EventEmitter. (/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. (/plejd/nodemodules/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) 2023-10-14 08:13:07 INF [plejd-ble] BLE init done, waiting for devices. 2023-10-14 08:13:09 INF [plejd-ble] Device discovery done, found 1 Plejd devices 2023-10-14 08:13:09 INF [plejd-ble] Connecting to /org/bluez/hci0/dev_E8_EB_65_A7_1B_44 2023-10-14 08:13:20 INF [plejd-ble] onDeviceConnected() 2023-10-14 08:13:20 ERR [plejd-ble] unable to enumerate characteristics. 2023-10-14 08:13:20 ERR [plejd-ble] Could not connect to any Plejd device. Starting reconnect loop... 2023-10-14 08:13:20 INF [plejd-ble] Starting reconnect loop... 2023-10-14 08:13:20 INF [device-comm] Bluetooth reconnecting... 2023-10-14 08:13:25 INF [plejd-ble] Reconnecting BLE... 2023-10-14 08:13:25 INF [plejd-ble] init() 2023-10-14 08:13:30 INF [plejd-ble] disconnecting /org/bluez/hci0/dev_E8_EB_65_A7_1B_44. This can take up to 180 seconds 2023-10-14 08:13:32 INF [plejd-ble] BLE init done, waiting for devices. 2023-10-14 08:13:34 INF [plejd-ble] Device discovery done, found 1 Plejd devices 2023-10-14 08:13:34 INF [plejd-ble] Connecting to /org/bluez/hci0/dev_CC_54_0E_CD_B2_40 2023-10-14 08:13:45 INF [plejd-ble] onDeviceConnected() 2023-10-14 08:13:45 INF [plejd-ble] Connected to Plejd device Plejd Smartplugg 1 (CC540ECDB240, BLE id 25). 2023-10-14 08:13:45 INF [plejd-ble] authenticate() 2023-10-14 08:13:45 INF [plejd-ble] BLE Connected to Plejd Smartplugg 1 2023-10-14 08:13:45 INF [plejd-ble] Plejd clock updates disabled in configuration. 2023-10-14 08:13:45 INF [plejd-ble] startPing() 2023-10-14 08:13:45 INF [device-comm] Bluetooth connected. Plejd BLE up and running! 2023-10-14 08:13:45 INF [device-comm] startWriteQueue()

piemar commented 1 year ago

I am having similar issues after the update, ai can't turn off lights.

Running version

Home Assistant 2023.10.3 Supervisor 2023.10.0 Operating System 11.0 Frontend 20231005.0 - latest Mosquito add on version:6.3.1 Plejd Addon version: 0.11.0 Blue tooth adapter:

When trying to turn on turn off I am getting below error:

2023-10-14 13:56:41 ERR [plejd-ble] Error handling /org/bluez/hci1/dev_E9_01_5A_0F_8B_5E Does Not Exist DBusError: Does Not Exist at _methodReturnHandlers. (/plejd/node_modules/dbus-next/lib/bus.js:343:27) at handleMessage (/plejd/node_modules/dbus-next/lib/bus.js:101:11) at EventEmitter. (/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. (/plejd/nodemodules/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) 2023-10-14 13:56:41 ERR [plejd-ble] Error handling /org/bluez/hci1/dev_04_B9_E3_65_79_EB

d96moe commented 1 year ago

Updated to 2023.10.0 (OS 10.5) and it has been working for three days now.

Thank you for your update @d96moe, I'd urge you to have a look at: home-assistant/core#99909 and see if you have the same issues.

Seems not to be the same issue. Hassos 11 updates to the bt stack broke hassio-plejd. https://github.com/icanos/hassio-plejd/issues/292

piemar commented 1 year ago

Updated to 2023.10.0 (OS 10.5) and it has been working for three days now. Thank you for your update @d96moe, I'd urge you to have a look at: home-assistant/core#99909 and see if you have the same issues.

Seems not to be the same issue. Hassos 11 updates to the bt stack broke hassio-plejd. #292

I downgraded to below versions and everything started working.

HassiOS ha os update --version 10.5

HassioCore ha core update --version 2023.10.3