constant mqtt close

[lutierigb]

Hi

Great work! I used to use another project that send commands via bluetooth but there was no integration with HA. I just love to see the Covers in HA now that I'm running your project.

However, I'm running into an issue every now and then where it doesn't send the discovery message to HA(I believe) and you can see that something isn't right as it constantly logs mqtt close messages.

root@ubuntu:/am43# NOBLE_HCI_DEVICE_ID=0 /am43/node_modules/.bin/am43ctrl 025964f227b3 02c9051179b3  --url mqtt://192.168.1.1:1863 -p xxx -u admin -d
  am43* scanning for 2 device(s) [ '025964f227b3', '02c9051179b3' ] +0ms
  am43* discovered 025964f227b3 +186ms
  am43 Found 6690250b0b77 but will not connect as it was not specified in the list of devices [ '025964f227b3', '02c9051179b3' ] +0ms
  am43 Found 612757372771 but will not connect as it was not specified in the list of devices [ '025964f227b3', '02c9051179b3' ] +35ms
  am43 Found 7bfde96bbaff but will not connect as it was not specified in the list of devices [ '025964f227b3', '02c9051179b3' ] +77ms
  am43* discovered 02c9051179b3 +163ms
  am43* all expected devices connected, stopping scan +0ms
  am43:025964f227b3 mqtt topic homeassistant/cover/025964f227b3 +0ms
  am43:025964f227b3 interval: 1200000 +0ms
  am43:02c9051179b3 mqtt topic homeassistant/cover/02c9051179b3 +0ms
  am43:02c9051179b3 interval: 720000 +0ms
  am43:025964f227b3 mqtt offline +5ms
  am43:025964f227b3 mqtt close +1ms
  am43:02c9051179b3 mqtt offline +4ms
  am43:02c9051179b3 mqtt close +0ms
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:02c9051179b3 Connection busy for other device, delaying data read... +989ms
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +12ms
  am43:025964f227b3 AM43 connected for data reading +926ms
  am43:02c9051179b3 Connection busy for other device, delaying data read... +989ms
  am43:025964f227b3 mqtt close +74ms
  am43:02c9051179b3 mqtt close +11ms
  am43:025964f227b3 discovered data char +104ms
  am43:025964f227b3 received characteristic update +75ms
  am43:025964f227b3 Notification data: 9aa205000000005a67 +0ms
  am43:025964f227b3 Notification identifier: a2 +0ms
  am43:025964f227b3 Bat %: 90 +0ms
  am43:025964f227b3 received characteristic update +29ms
  am43:025964f227b3 Notification data: 9aaa02000230 +0ms
  am43:025964f227b3 Notification identifier: aa +0ms
  am43:025964f227b3 Light %: 2 +0ms
  am43:025964f227b3 received characteristic update +51ms
  am43:025964f227b3 Notification data: 9aa7071f322b000000300c +0ms
  am43:025964f227b3 Notification identifier: a7 +0ms
  am43:025964f227b3 Position %: 43 +0ms
  am43:025964f227b3 Reading data completed +0ms
  am43:025964f227b3 received characteristic update +9ms
  am43:025964f227b3 Notification data: 9aa80032 +1ms
  am43:025964f227b3 Notification identifier: a8 +0ms
  am43:025964f227b3 Reading data completed +0ms
  am43:025964f227b3 received characteristic update +21ms
  am43:025964f227b3 Notification data: 9aa9100000001100000000010000110000000022 +0ms
  am43:025964f227b3 Notification identifier: a9 +1ms
  am43:025964f227b3 Reading data completed +0ms
  am43:02c9051179b3 Connection busy for other device, delaying data read... +990ms
  am43:025964f227b3 mqtt close +710ms
  am43:02c9051179b3 mqtt close +12ms
  am43:025964f227b3 disconnected for data reading +269ms
  am43:025964f227b3 Reading data was successful +0ms
  am43:025964f227b3 state changed received: {"id":"025964f227b3","lastconnect":"2020-05-21T04:40:58.256Z","lastaction":null,"state":"OPEN","battery":90,"light":2,"position":43} +1ms
  am43:025964f227b3 mqtt close +732ms
  am43:02c9051179b3 mqtt close +1s
  am43:02c9051179b3 AM43 connected for data reading +891ms
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +110ms
  am43:02c9051179b3 discovered data char +39ms
  am43:02c9051179b3 received characteristic update +75ms
  am43:02c9051179b3 Notification data: 9aa205000000004e73 +0ms
  am43:02c9051179b3 Notification identifier: a2 +0ms
  am43:02c9051179b3 Bat %: 78 +0ms
  am43:02c9051179b3 received characteristic update +45ms
  am43:02c9051179b3 Notification data: 9aaa02000133 +0ms
  am43:02c9051179b3 Notification identifier: aa +0ms
  am43:02c9051179b3 Light %: 1 +0ms
  am43:02c9051179b3 received characteristic update +60ms
  am43:02c9051179b3 Notification data: 9aa7071f32000bb8123086 +0ms
  am43:02c9051179b3 Notification identifier: a7 +0ms
  am43:02c9051179b3 Position %: 0 +0ms
  am43:02c9051179b3 Reading data completed +0ms
  am43:02c9051179b3 received characteristic update +1ms
  am43:02c9051179b3 Notification data: 9aa80032 +0ms
  am43:02c9051179b3 Notification identifier: a8 +0ms
  am43:02c9051179b3 Reading data completed +0ms
  am43:02c9051179b3 received characteristic update +59ms
  am43:02c9051179b3 Notification data: 9aa9100000001100000000010000110000000022 +0ms
  am43:02c9051179b3 Notification identifier: a9 +0ms
  am43:02c9051179b3 Reading data completed +0ms
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +723ms
  am43:02c9051179b3 disconnected for data reading +239ms
  am43:02c9051179b3 Reading data was successful +0ms
  am43:02c9051179b3 state changed received: {"id":"02c9051179b3","lastconnect":"2020-05-21T04:41:01.224Z","lastaction":null,"state":"OPEN","battery":78,"light":1,"position":0} +0ms
noble warning: unknown handle 70 disconnected!
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +762ms
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
  am43:025964f227b3 mqtt close +1s
  am43:02c9051179b3 mqtt close +1s
...

and it never stops logging "mqtt close +1s"

any ideas what that might be?

[binsentsu]

According to the docs of the mqtt library, the close event is emmitted from the upon disconnection. Do you see disconnections in your broker log also?

[lutierigb]

i think part of the issue is that there is no "mqtt connected" message. I'm currently not logging connection attempts in the broker but I'll do some further investigation and update the bug if I find anything.

[TheFonix]

Any luck on this? as im seeing the same issue