search

binsentsu / am43-ctrl

Node Util for controlling an AM43 Blinds Drive Cover, either over MQTT or via a HTTP API
44 stars 25 forks source link

[bug] Connection busy for other device, delaying data read #22

Open timdonovanuk opened 3 years ago

timdonovanuk commented 3 years ago

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
timdonovanuk commented 3 years ago

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
timdonovanuk commented 3 years ago

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

> usb@1.6.3 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 am43-ctrl@0.2.0: 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: am43-ctrl@0.2.0
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: usb@1.6.3 (node_modules/usb):
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: usb@1.6.3 install: `prebuild-install --verbose || node-gyp rebuild`
npm WARN optional SKIPPING OPTIONAL DEPENDENCY: Exit status 1
binsentsu commented 3 years ago

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)

timdonovanuk commented 3 years ago

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
timdonovanuk commented 3 years ago

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

timdonovanuk commented 3 years ago

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 :)

timdonovanuk commented 3 years ago

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!

Wolbyworld commented 3 years ago

Same issue here. Not sure I can provide any additional information. Running in RPI4

bachoo786 commented 1 year ago

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!

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