binsentsu
[bug] Connection busy for other device, delaying data read
Hi,
I think one of my blinds is very low on power, and although the initial connection works, it doesn't actually respond. This app gets stuck waiting for a response that never arrives:
$ sudo /home/pi/aok_mqtt/node_modules/.bin/am43ctrl 02:5A:5E:B7:AA:B5 02:18:89:A0:F8:4A -l 3001 -d --url mqtt://192.168.1.5 -u mqtt -p
am43* scanning for 2 device(s) [ '025a5eb7aab5', '021889a0f84a' ] +0ms
am43 listening on port 3001 +0ms
am43 Found f333192b7832 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +49ms
am43 Found e1a170935be3 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +15ms
am43 Found a4307a81d77d but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +8ms
am43 Found d629f4cdb522 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +17ms
am43 Found dff9288667b1 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +7ms
am43 Found e615fc138814 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +12ms
am43 Found 3902c1e3c19b but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +39ms
am43 Found 1a77baca0051 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +14ms
am43 Found 29247018b645 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +9ms
am43 Found 7c23939cc305 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +27ms
am43 Found f33386ad232b but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +8ms
am43 Found f33335248411 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +16ms
am43 Found 33cb747b9b61 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +56ms
am43 Found 4a523534aa24 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +67ms
am43* discovered 025a5eb7aab5 +1s
am43 Found 8c79f51901c7 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +389ms
am43 Found 67701951a2f4 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +266ms
am43 Found 09704f1bdd5f but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +56ms
am43 Found 2ea9439c9e11 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5', '021889a0f84a' ] +73ms
am43* discovered 021889a0f84a +594ms
am43* all expected devices connected, stopping scan +0ms
am43:025a5eb7aab5 mqtt topic homeassistant/cover/025a5eb7aab5 +0ms
am43:025a5eb7aab5 interval: 1140000 +1ms
am43:021889a0f84a mqtt topic homeassistant/cover/021889a0f84a +0ms
am43:021889a0f84a interval: 1020000 +1ms
am43:025a5eb7aab5 mqtt connected +23ms
am43:021889a0f84a mqtt connected +27ms
am43:021889a0f84a Connection busy for other device, delaying data read... +5s
am43:025a5eb7aab5 AM43 connected for data reading +6s
am43:025a5eb7aab5 discovered data char +115ms
am43:025a5eb7aab5 received characteristic update +74ms
am43:025a5eb7aab5 Notification data: 9aa205000000006459 +0ms
am43:025a5eb7aab5 Notification identifier: a2 +1ms
am43:025a5eb7aab5 Bat %: 100 +0ms
am43:025a5eb7aab5 received characteristic update +40ms
am43:025a5eb7aab5 Notification data: 9a00015a31 +1ms
am43:025a5eb7aab5 Notification identifier: 00 +0ms
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
am43:021889a0f84a Connection busy for other device, delaying data read... +1s
If I remove the trouble device (i.e. 02:18:89:A0:F8:4A) from the startup command, so that only the other blind is specified, it works no problems!
@pi1:~/aok_mqtt $ sudo /home/pi/aok_mqtt/node_modules/.bin/am43ctrl 02:5A:5E:B7:AA:B5 -l 3001 -d --url mqtt://192.168.1.5 -u mqtt -p
am43* scanning for 1 device(s) [ '025a5eb7aab5' ] +0ms
am43 listening on port 3001 +0ms
am43 Found dff9288667b1 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +33ms
am43 Found d629f4cdb522 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +2ms
am43 Found e1a170935be3 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +3ms
am43 Found 4a523534aa24 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +11ms
am43 Found 278afc0a9a0a but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +8ms
am43 Found 33cb747b9b61 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +17ms
am43 Found 021889a0f84a but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +4ms
am43 Found f333192b7832 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +33ms
am43 Found e615fc138814 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +70ms
am43 Found 1a77baca0051 but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +15ms
am43* discovered 025a5eb7aab5 +721ms
am43* all expected devices connected, stopping scan +0ms
am43:025a5eb7aab5 mqtt topic homeassistant/cover/025a5eb7aab5 +0ms
am43:025a5eb7aab5 interval: 1140000 +1ms
am43:025a5eb7aab5 mqtt connected +25ms
am43:025a5eb7aab5 AM43 connected for data reading +6s
am43:025a5eb7aab5 discovered data char +159ms
am43:025a5eb7aab5 received characteristic update +72ms
am43:025a5eb7aab5 Notification data: 9aa205000000006459 +1ms
am43:025a5eb7aab5 Notification identifier: a2 +1ms
am43:025a5eb7aab5 Bat %: 100 +0ms
am43:025a5eb7aab5 received characteristic update +41ms
am43:025a5eb7aab5 Notification data: 9a00015a31 +0ms
am43:025a5eb7aab5 Notification identifier: 00 +1ms
Hmm I was wrong, even with just the one device specified, although it doesn't immediately get stuck in a loop, as soon as I issue a command it does:
am43:025a5eb7aab5 mqtt message received 'homeassistant/cover/025a5eb7aab5/set', 'OPEN' +3m
am43:025a5eb7aab5 requesting cover open +2ms
am43:025a5eb7aab5 Connection busy for other device, waiting... +1ms
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
The only other info I can share is I'm running on a Pi3, with nodejs 12.20.0 (nodejs 14 wouldn't even npm install this project). I had the following error during installation:
pi@pi1:~/aok_mqtt $ npm install https://github.com/binsentsu/am43-ctrl
> [email protected] install /home/pi/aok_mqtt/node_modules/usb
> prebuild-install --verbose || node-gyp rebuild
prebuild-install info begin Prebuild-install version 5.3.6
prebuild-install info looking for cached prebuild @ /home/pi/.npm/_prebuilds/cd9f6c-usb-v1.6.3-node-v83-linux-arm.tar.gz
prebuild-install http request GET https://github.com/tessel/node-usb/releases/download/v1.6.3/usb-v1.6.3-node-v83-linux-arm.tar.gz
prebuild-install http 404 https://github.com/tessel/node-usb/releases/download/v1.6.3/usb-v1.6.3-node-v83-linux-arm.tar.gz
prebuild-install WARN install No prebuilt binaries found (target=14.15.1 runtime=node arch=arm libc= platform=linux)
make: Entering directory '/home/pi/aok_mqtt/node_modules/usb/build'
CC(target) Release/obj.target/libusb/libusb/libusb/core.o
CC(target) Release/obj.target/libusb/libusb/libusb/descriptor.o
CC(target) Release/obj.target/libusb/libusb/libusb/hotplug.o
CC(target) Release/obj.target/libusb/libusb/libusb/io.o
CC(target) Release/obj.target/libusb/libusb/libusb/strerror.o
CC(target) Release/obj.target/libusb/libusb/libusb/sync.o
CC(target) Release/obj.target/libusb/libusb/libusb/os/poll_posix.o
CC(target) Release/obj.target/libusb/libusb/libusb/os/threads_posix.o
CC(target) Release/obj.target/libusb/libusb/libusb/os/linux_usbfs.o
CC(target) Release/obj.target/libusb/libusb/libusb/os/linux_udev.o
../libusb/libusb/os/linux_udev.c:40:10: fatal error: libudev.h: No such file or directory
#include <libudev.h>
^~~~~~~~~~~
compilation terminated.
make: *** [libusb.target.mk:148: Release/obj.target/libusb/libusb/libusb/os/linux_udev.o] Error 1
make: Leaving directory '/home/pi/aok_mqtt/node_modules/usb/build'
gyp ERR! build error
gyp ERR! stack Error: `make` failed with exit code: 2
gyp ERR! stack at ChildProcess.onExit (/usr/lib/node_modules/npm/node_modules/node-gyp/lib/build.js:194:23)
gyp ERR! stack at ChildProcess.emit (events.js:315:20)
gyp ERR! stack at Process.ChildProcess._handle.onexit (internal/child_process.js:277:12)
gyp ERR! System Linux 4.19.97-v7+
gyp ERR! command "/usr/bin/node" "/usr/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js" "rebuild"
gyp ERR! cwd /home/pi/aok_mqtt/node_modules/usb
gyp ERR! node -v v14.15.1
gyp ERR! node-gyp -v v5.1.0
gyp ERR! not ok
npm WARN saveError ENOENT: no such file or directory, open '/home/pi/aok_mqtt/package.json'
npm WARN notsup Unsupported engine for [email protected]: wanted: {"node":">=10.16.0 <13.0"} (current: {"node":"14.15.1","npm":"6.14.8"})
npm WARN notsup Not compatible with your version of node/npm: [email protected]
npm WARN enoent ENOENT: no such file or directory, open '/home/pi/aok_mqtt/package.json'
npm WARN aok_mqtt No description
npm WARN aok_mqtt No repository field.
npm WARN aok_mqtt No README data
npm WARN aok_mqtt No license field.
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] (node_modules/usb):
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] install: `prebuild-install --verbose || node-gyp rebuild`
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: Exit status 1
It seems that the data reading sequence for battery etc does not complete and somewhere hangs (unless your log snipped was not complete)
The log should end with 'data reading successful':
Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.678Z am43:02525911db94 AM43 connected for data reading Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.798Z am43:02525911db94 discovered data char Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.902Z am43:02525911db94 received characteristic update Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.903Z am43:02525911db94 Notification data: 9aa205000000003b06 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.903Z am43:02525911db94 Notification identifier: a2 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.903Z am43:02525911db94 Bat %: 59 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.932Z am43:02525911db94 received characteristic update Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.933Z am43:02525911db94 Notification data: 9aaa02000032 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.933Z am43:02525911db94 Notification identifier: aa Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.933Z am43:02525911db94 Light %: 0 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.977Z am43:02525911db94 received characteristic update Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.978Z am43:02525911db94 Notification data: 9aa7070e320008fc1230d0 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.978Z am43:02525911db94 Notification identifier: a7 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.978Z am43:02525911db94 Position %: 0 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.978Z am43:02525911db94 Reading data completed Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.993Z am43:02525911db94 received characteristic update Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.993Z am43:02525911db94 Notification data: 9aa80032 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.993Z am43:02525911db94 Notification identifier: a8 Dec 01 08:03:40 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:40.993Z am43:02525911db94 Reading data completed Dec 01 08:03:41 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.008Z am43:02525911db94 received characteristic update Dec 01 08:03:41 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.008Z am43:02525911db94 Notification data: 9aa9100000001100000000010000110000000022 Dec 01 08:03:41 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.009Z am43:02525911db94 Notification identifier: a9 Dec 01 08:03:41 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.009Z am43:02525911db94 Reading data completed Dec 01 08:03:41 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.998Z am43:02525911db94 disconnected for data reading Dec 01 08:03:42 raspberrypi am43ctrl[1309]: 2020-12-01T08:03:41.999Z am43:02525911db94 Reading data was successful
You can try to update the Bluez drivers on raspbian. Command 'bluetoothctl -v' shows you your current version.
Tutorial: https://github.com/zewelor/bt-mqtt-gateway/wiki/Upgrade-Bluez-on-Raspbian
Check for latest version (seems to be bluez-5.55.tar.gz at this moment)
Hey thanks @binsentsu. I was on 5.50 already but upgraded to 5.55. No difference. It stops doing anything after Notification identifier: 00 +1ms unless I issue a command, and then it goes into the stuck loop.
For what it's worth, I was previously using this project, which connects and issues commands, and gets the status fine (but lacks HA/mqtt):
https://github.com/TheBazeman/A-OK-AM43-Blinds-Drive/blob/master/AOK-AM43.py
I've also used
pi@pi1:~ $ sudo /home/pi/aok_mqtt/node_modules/.bin/am43ctrl 02:5A:5E:B7:AA:B5 -l 3001 -d --url mqtt://192.168.1.5 -u mqtt -p -d
am43* scanning for 1 device(s) [ '025a5eb7aab5' ] +0ms
am43 listening on port 3001 +0ms
am43* discovered 025a5eb7aab5 +1s
am43* all expected devices connected, stopping scan +0ms
am43:025a5eb7aab5 mqtt topic homeassistant/cover/025a5eb7aab5 +0ms
am43:025a5eb7aab5 interval: 600000 +1ms
am43 Found 5e472010d24c but will not connect as it was not specified in the list of devices [ '025a5eb7aab5' ] +303ms
am43:025a5eb7aab5 mqtt connected +29ms
am43:025a5eb7aab5 AM43 connected for data reading +5s
am43:025a5eb7aab5 discovered data char +111ms
am43:025a5eb7aab5 received characteristic update +74ms
am43:025a5eb7aab5 Notification data: 9aa205000000006459 +0ms
am43:025a5eb7aab5 Notification identifier: a2 +1ms
am43:025a5eb7aab5 Bat %: 100 +0ms
am43:025a5eb7aab5 received characteristic update +43ms
am43:025a5eb7aab5 Notification data: 9a00015a31 +0ms
am43:025a5eb7aab5 Notification identifier: 00 +1ms
am43:025a5eb7aab5 mqtt message received 'homeassistant/cover/025a5eb7aab5/set', 'STOP' +2m
am43:025a5eb7aab5 requesting cover stop +1ms
am43:025a5eb7aab5 Connection busy for other device, waiting... +2ms
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
am43:025a5eb7aab5 Connection busy for other device, waiting... +1s
So looking at where mine hangs, am I understanding the code right, it looks like mine fails reading the light data? My "notification identifier" seem to be different, yours is aa, mine is 00
Your log:
am43:02525911db94 Bat %: 59 Dec 01 08:03:40 am43:02525911db94 received characteristic update Dec 01 08:03:40 am43:02525911db94 Notification data: 9aaa02000032 Dec 01 08:03:40 am43:02525911db94 Notification identifier: aa Dec 01 08:03:40 am43:02525911db94 Light %: 0 Dec 01 08:03:40 raspberrypi am43:02525911db94 received characteristic update Dec 01 08:03:40
My log:
am43:025a5eb7aab5 Bat %: 100 +0ms am43:025a5eb7aab5 received characteristic update +43ms am43:025a5eb7aab5 Notification data: 9a00015a31 +0ms am43:025a5eb7aab5 Notification identifier: 00 +1ms
I think the issue is that these are defined in the code:
const batteryNotificationIdentifier = "a2";
const positionNotificationIdentifier = "a7";
const lightNotificationIdentifier = "aa";
but mine is returning 00. Looking at the code, I think there is no else if statement to handle when the NotificationIdentifier is not one of those 3 above, so the app just hangs. I'm not really a developer so just a guess :)
I tried adding:
else {
self.writeLog('Notification identifier unknown');
self.writeLog('Skipping');
}
to the discoveryResult function, which it outputs but it still gets stuck. I guess as you said, something odd is happening in the readData() function, since "delaying data read" is what it eventually outputs.
It's not clear to me where this function (readData) is actually called. I suppose what is supposed to happen is discoveryResult - characteristic.on('data', function (data, isNotification) {} loops until battery, light and position are found. I don't understand the code enough, as I cannot see readData() being called anywhere in this loop :( I added some logging and confirmed this is where it gets stuck:
am43:025a5eb7aab5 entering readData() +0ms
am43:025a5eb7aab5 Connection busy for other device, delaying data read... +0ms
Any chance of adding some error handling here or a timeout? Many thanks!
Same issue here. Not sure I can provide any additional information. Running in RPI4
I tried adding:
else { self.writeLog('Notification identifier unknown'); self.writeLog('Skipping'); }to the
discoveryResultfunction, which it outputs but it still gets stuck. I guess as you said, something odd is happening in the readData() function, since "delaying data read" is what it eventually outputs.It's not clear to me where this function (readData) is actually called. I suppose what is supposed to happen is discoveryResult -
characteristic.on('data', function (data, isNotification) {}loops until battery, light and position are found. I don't understand the code enough, as I cannot see readData() being called anywhere in this loop :( I added some logging and confirmed this is where it gets stuck:am43:025a5eb7aab5 entering readData() +0ms am43:025a5eb7aab5 Connection busy for other device, delaying data read... +0msAny chance of adding some error handling here or a timeout? Many thanks!
did you manage to resolve this? I am having the exact same issue as you described in your OP. @binsentsu can you please look into this? thanks
