Multiple event firings due to leaking BLE event listeners on Raspberry Pi 3 about homebridge-bluetooth HOT 18 CLOSED

OK, so did a full refresh of everything. Seems like the node version that shipped with the pi was being used and the upgrade did not work.

Everything seems to have went fine. I had error pop up during the install of noble. BUT it seems to have installed.

I don't seem to have the utf8 issue anymore but it's still not working. Well if I keep deleting the accessory and restarting homebridge in debug mode, I get it to work sometimes.

I've attached a file with a copy of the debug information when I run homebridge. You will see in this file two runs of homebridge. The first run is a run that did not work and it "hanged" in the last few statements after it attempts to read from the device - it times out there and move on. At that point you'll see I stopped it and restarted. This second run it seems to actually work and the data is read and written back and forth correctly.

Any thoughts on what I can try?

dump-notworkthenwork.docx

from homebridge-bluetooth.

Yeah, Node.js is changing very quickly and most linux distros don't have a version that's anywhere close to recent. It's weird that npm even installed the plugin since package.json demands Node.js >= 4.3.2 I checked and Homebridge itself requires the same version. Good thing that you resolved this problem, though!

After comparing your two run logs, I remember experiencing a similar Connect-Disconnect behavior some time ago on my RPi3. It disappeared for me recently and I don't remember doing anything special....

Even after Googling around for quite a bit I don't have a clue why is the Connect-Disconnect happening. There's a note about this behavior in the troubleshooting section Can you try running the hciconfig to reset the BLE adapter and then start the Homebridge server? Like this:

[sudo] hciconfig hci0 reset && [sudo] homebridge

Note: When submitting logs, people generally prefer text files to Word documents. You can easily create a pure text output log, for example with the tee command:

DEBUG=* homebridge | tee log1.txt

tee is a simple utility that writes input to the specified file and also displays it on the screen at the same time.

from homebridge-bluetooth.

Ok Thanks.

Should I try downgrading node though? I'm on the latest -> 7.x... And I think there is an issue with the Bonjour discovery. Loosing wifi and stuff messes it up sometimes and need to restart the server. Not sure if all those little things are a potential problem with the node versions

I actually wrote the HCIconfig line into the rc.local file so it runs on startup (as well as remove the peskie accessories folder).

Is there also a specific version of noble I should be using?

Will attempt to redo the system again later in the week if you think that will help (going down to specific versions) so if you can hit the the version of noble I should probably drop to that works for you as well?

Has your experience on the Pi3 been rock solid? I feel like I keep having to do restarts and re-addition of the bridge to the home app as well - hopefully a downgrade will help with all of that?

The other thing that I was wondering can affect this and might be a separate issue: as far as I can tell (still need to verify with the code) the plugin maintains a connection with the ble device once setup? Is that how it's supposed to work? I'm a little new, but somehow I expected to only connect when there was data to write. Other than that it would be reading the Craracteristics? But My assumption may be wrong as I read somewhere to maintain a notify relationship with the characteristic the main device needs to maintain a connect relationship with the device?

from homebridge-bluetooth.

Personally I wouldn't use the 7.x version of Node. I prefer the LTS releases. Nor this plugin nor Homebridge need any of the new functionality since 4.x as far as I know.

That being said, there's no specific version to use. I have Node.js 4.5.0 and Noble 1.7.0 on my RPi3 and there are no issues whatsoever - i.e. every problem I experienced was caused by a bug in my code 😄 I haven't done any long term test as I frequently re-start the server because of the development, but in the meantime between code changes it's been very stable.

Yes, you're correct - the BLE connection is meant to be on all the time. If it would be only for writing or reading there would be no need to do this, but permanent connection is crucial for notifications. Imagine for example a lamp with a switch like in the rgb-lightbulb example. When the switch is pressed, thanks to the notification mechanism, this information gets immediately reflected in the Home app on iOS.

Without this mechanism there would be no LE in BLE, since one would have to constantly poll (i.e read) the lamp for on/off state. Which, of cource, wouldn't allow any Low Energy operation since the lamp doesn't change state very frequently.

from homebridge-bluetooth.

Hmmm Ok. I'll try downgrading as soon as I get a chance this week and will look at the RSSI stuff.

I'm on a RPi3MB with Jessie. You think it could have anything to do with the drivers/BLE hardware? I tried it on 2 different boards (I got like 4 to test with) so I don't think it's a hardware failure but potentially and issue with the chip they used?

from homebridge-bluetooth.

Driver problem may be the case here, depending on the kernel version you use. Here's another idea - please, take a look here. Then get the server running, start another console and take a look at output of dmesg and hcidump.

According to the #242 from noble it should look like:

2015-09-22 17:03:37.964308 < HCI Command: Disconnect (0x01|0x0006) plen 3
handle 71 reason 0x13

If this happens to be the case, the fix is to install a newer kernel.

from homebridge-bluetooth.

This may sound dumb, but shouldn't Raspbian Jessie have the latest kernel for the Pi?

from homebridge-bluetooth.

I don't know what version it ships with (My guess is 4.4.x), but linux distributions typically provide packages for various kernel versions. So you can have more or less whatever version you wish. Running uname -a will tell you the exact version.

from homebridge-bluetooth.

Hmm good information, thanks. I will dig into this after my meetings tomorrow.

The thread seems to have good information, though I'd assume I installed the latest stuff which should have fixed this SO I don't believe I'm suffering from this (Also when I do get a connection, it's maintained as long as I don't restart or manually disconnect or something). BUT it's worth a try if even to learn a bit more about these technologies.

I'll let you know how these go and if it solves the issue here.

from homebridge-bluetooth.

OK, Finally got some spare time to tinker with this stuff today.

Verified that is all works well on the mac. You can switch off the hombridge server and the device in random order and things still work well etc.

HOWEVER on the raspberry, you will randomly get it working with the device. It will work fine until the devices get disconnected and reconnects. At that point things just don't work right. Basically the same information as I sent before.

I was able to downgrade node, but only to 4.7 for some reason. I couldn't get my hand on 4.5 for raspberry. Let me know if you know how to do this and I'll give that a go as well. I also tried the stuff with the kernel you pointed me to, does not seem to be the issue.

I'm pretty bummed, as I have 4 raspberry pi 3 model b's that I was hoping to deploy around the house before Christmas to work with some of the accessories I created.

I can't seem to zero in on the problem. Does the plugin/homebridge expect anything special from the firmware that run on the accessories?

At this point I'm wondering if it'll make sense getting a copy of your full OS and settings etc for you pi and try it on mine.

I'm attaching some random dumps of HCIDump and Homebridge debug information in case you are able to see anything interesting that might help
HCIDump.txt
Dump.txt
error2.txt
Error.txt

from homebridge-bluetooth.

Also, here are some more dumps.

There's a dump of homebridge when the server starts and the connection to the BLE device does not work. Basically it says Updating for a while in the home app and then says no response (startupincorrect.txt)

There's a dump of Homebridge when the server starts and the link with the Bluetooth device is successful and seems to work fine until the link breaks

There's a dump using HCIDump of the stuff while homebridge was working

HomebridgeDebugDumpwhenItWorked.txt

HCIDumpWhenItFailedandThenWorked.txt
startupIncorrect.txt

from homebridge-bluetooth.

OK. So found something interesting here. Have no idea if this can account for the problem.

In the startupIncorrect.txt file I'm noticing that 3 attempts to connect to the device were made after it was discovered. Only the last attempt was successful - which is weird. BUT when the last one is successful, it seems that the code then connects to the service and the characteristics 3 times each! I believe that some handerlers are also in play here so I'm wondering if these can be partially responsible for the effect where I'm seeing that the device is picked up on Homekit, but is stuck on "updating" for a while and then goes to "no response". Perhaps the multiple handlers create some issue with the read returning properly or causes the BLE stuff to hang?

I'm still digging, but I'm posting here in case you may have better insight on what I'm finding. Here's the output that shows the multiple adds of the characteristics and services:

[12/24/2016, 9:22:05 PM] [LightBot] Argh! Connected | LightBot - EC:F1:13:4C:C8:53
  hci onSocketData: 011620024000 +3ms
  hci 	event type = 1 +1ms
  hci 		cmd = 8214 +0ms
  hci 		data len = 2 +0ms
  hci onSocketData: 040f0400011620 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 15 +0ms
  hci 		status = 0 +1ms
  hci 		cmd = 8214 +0ms
  hci onSocketData: 010c20020000 +0ms
  hci 	event type = 1 +0ms
  hci 		cmd = 8204 +0ms
  hci 		data len = 2 +0ms
  hci 			LE enable scan command +1ms
  hci 			enable scanning = false +0ms
  hci 			filter duplicates = false +0ms
  noble scanStop +0ms
  hci onSocketData: 040e04010c2000 +0ms
  hci 	event type = 4 +1ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 8204 +0ms
  hci 		status = 0 +0ms
  hci 		result =  +0ms
  hci onSocketData: 043e0c040040000100000000000000 +0ms
  hci 	event type = 4 +1ms
  hci 	sub event type = 62 +0ms
  hci 		LE meta event type = 4 +0ms
  hci 		LE meta event status = 0 +0ms
  hci 		LE meta event data = 40000100000000000000 +0ms
  hci onSocketData: 024020070003000400031700 +16ms
  hci 	event type = 2 +1ms
  hci 		cid = 4 +1ms
  hci 		handle = 64 +0ms
  hci 		data = 031700 +0ms
  att ec:f1:13:4c:c8:53: read: 031700 +2ms
  att ec:f1:13:4c:c8:53: new MTU is 23 +1ms
  att ec:f1:13:4c:c8:53: write: 100100ffff0028 +0ms
  hci write acl data pkt - writing: 0240000b0007000400100100ffff0028 +1ms
  hci onSocketData: 024020180014000400110601000700001808000b0001180c00ffff00a0 +35ms
  hci 	event type = 2 +1ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +0ms
  hci 		data = 110601000700001808000b0001180c00ffff00a0 +0ms
  att ec:f1:13:4c:c8:53: read: 110601000700001808000b0001180c00ffff00a0 +1ms
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1800
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1801
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Connected | Service.Lightbulb - A000
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1800
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1801
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Connected | Service.Lightbulb - A000
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1800
[12/24/2016, 9:22:05 PM] [LightBot] Ignored | Service - 1801
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Connected | Service.Lightbulb - A000
  att ec:f1:13:4c:c8:53: write: 080c00ffff0328 +76ms
  hci write acl data pkt - writing: 0240000b0007000400080c00ffff0328 +0ms
  hci onSocketData: 02402014001000040009070d001a0e0001a0100002110002a0 +46ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +1ms
  hci 		data = 09070d001a0e0001a0100002110002a0 +0ms
  att ec:f1:13:4c:c8:53: read: 09070d001a0e0001a0100002110002a0 +0ms
  att ec:f1:13:4c:c8:53: write: 080c00ffff0328 +1ms
  hci write acl data pkt - writing: 0240000b0007000400080c00ffff0328 +1ms
  hci onSocketData: 02402014001000040009070d001a0e0001a0100002110002a0 +27ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +0ms
  hci 		data = 09070d001a0e0001a0100002110002a0 +0ms
  att ec:f1:13:4c:c8:53: read: 09070d001a0e0001a0100002110002a0 +1ms
  att ec:f1:13:4c:c8:53: write: 080c00ffff0328 +0ms
  hci write acl data pkt - writing: 0240000b0007000400080c00ffff0328 +1ms
  hci onSocketData: 02402014001000040009070d001a0e0001a0100002110002a0 +28ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +1ms
  hci 		data = 09070d001a0e0001a0100002110002a0 +0ms
  att ec:f1:13:4c:c8:53: read: 09070d001a0e0001a0100002110002a0 +0ms
  att ec:f1:13:4c:c8:53: write: 081200ffff0328 +1ms
  hci write acl data pkt - writing: 0240000b0007000400081200ffff0328 +0ms
  hci onSocketData: 024020090005000400010812000a +27ms
  hci 	event type = 2 +1ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +0ms
  hci 		data = 010812000a +0ms
  att ec:f1:13:4c:c8:53: read: 010812000a +1ms
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] [On] Connected | Characteristic.On - A001
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Ignored | Characteristic - a002
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] [On] Connected | Characteristic.On - A001
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Ignored | Characteristic - a002
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] [On] Connected | Characteristic.On - A001
[12/24/2016, 9:22:05 PM] [LightBot] [Test Light] Ignored | Characteristic - a002
  att ec:f1:13:4c:c8:53: write: 081200ffff0328 +37ms
  hci write acl data pkt - writing: 0240000b0007000400081200ffff0328 +1ms
  hci onSocketData: 024020090005000400010812000a +20ms
  hci 	event type = 2 +1ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +0ms
  hci 		data = 010812000a +0ms
  att ec:f1:13:4c:c8:53: read: 010812000a +0ms
  att ec:f1:13:4c:c8:53: write: 081200ffff0328 +2ms
  hci write acl data pkt - writing: 0240000b0007000400081200ffff0328 +0ms
  hci onSocketData: 024020090005000400010812000a +35ms

from homebridge-bluetooth.

ALSO you will notice for the above, in the server run that does not work you will notice that the connection is actually made, then disconnected for some reason until the third try.

Here's some stuff I'm noticing about the actual read call for the device.

See the readout that I'm seeing below. Seems like in the server that didn't work the read is never completing? It's not saying why, but I noticed a write as well directly after.

Ok from the readout that works:

Accessory [LifeBot Home] Getting value for Characteristic "On" +6ms
  att ec:f1:13:4c:c8:53: write: 0a0e00 +10s
  hci write acl data pkt - writing: 0240000700030004000a0e00 +0ms
  hci onSocketData: 0240200f000b0004000b30000000000000000000 +30ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +1ms
  hci 		handle = 64 +0ms
  hci 		data = 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: read: 0b30000000000000000000 +0ms
[12/24/2016, 9:34:07 PM] [LightBot] [Test Light] [On] Argh! Read Called | 
[12/24/2016, 9:34:07 PM] [LightBot] [Test Light] [On] Arghy! 0
[12/24/2016, 9:34:07 PM] [LightBot] [Test Light] [On] false
  Accessory [LifeBot Home] Got Characteristic "On" value: 0 +44ms
  EventedHTTPServer [::ffff:192.168.1.101] Muting event '2.14' notification for this connection since it originated here. +3ms
  EventedHTTPServer [::ffff:192.168.1.101] HTTP Response is finished +1ms
  EventedHTTPServer [::ffff:192.168.1.101] HTTP request: /characteristics +450ms
  HAPServer [CC:22:3D:E3:CE:31] HAP Request: PUT /characteristics +0ms

Readout from the server run that didn't work

HAPServer [CC:22:3D:E3:CE:31] HAP Request: GET /characteristics?id=2.14 +0ms
  Accessory [LifeBot Home] Getting value for Characteristic "On" +6ms
  att ec:f1:13:4c:c8:53: write: 0a0e00 +6s
  hci write acl data pkt - writing: 0240000700030004000a0e00 +1ms
  hci onSocketData: 0240200f000b0004000b30000000000000000000 +24ms
  hci 	event type = 2 +1ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +0ms
  hci 		data = 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: read: 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: write: 0a0e00 +1ms
  hci write acl data pkt - writing: 0240000700030004000a0e00 +0ms
  hci onSocketData: 0240200f000b0004000b30000000000000000000 +28ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +0ms
  hci 		handle = 64 +1ms
  hci 		data = 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: read: 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: write: 0a0e00 +0ms
  hci write acl data pkt - writing: 0240000700030004000a0e00 +0ms
  hci onSocketData: 0240200f000b0004000b30000000000000000000 +29ms
  hci 	event type = 2 +0ms
  hci 		cid = 4 +1ms
  hci 		handle = 64 +0ms
  hci 		data = 0b30000000000000000000 +0ms
  att ec:f1:13:4c:c8:53: read: 0b30000000000000000000 +0ms
  hci onSocketData: 01010c08fffffbff07f8bf3d +7s
  hci 	event type = 1 +1ms
  hci 		cmd = 3073 +0ms
  hci 		data len = 8 +0ms
  hci onSocketData: 040e0401010c00 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 3073 +1ms
  hci 		status = 0 +0ms
  hci 		result =  +0ms
  hci onSocketData: 010120081f00000000000000 +0ms
  hci 	event type = 1 +0ms
  hci 		cmd = 8193 +1ms
  hci 		data len = 8 +0ms
  hci onSocketData: 040e0401012000 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 14 +1ms
  hci 		cmd = 8193 +0ms
  hci 		status = 0 +0ms
  hci 		result =  +0ms
  hci onSocketData: 01011000 +0ms
  hci 	event type = 1 +0ms
  hci 		cmd = 4097 +0ms
  hci 		data len = 0 +2ms
  hci onSocketData: 040e0c0101100007b600070f000922 +0ms
  hci 	event type = 4 +1ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 4097 +2ms
  hci 		status = 0 +1ms
  hci 		result = 07b600070f000922 +0ms
  hci onSocketData: 016d0c020100 +0ms
  hci 	event type = 1 +0ms
  hci 		cmd = 3181 +0ms
  hci 		data len = 2 +1ms
  hci onSocketData: 040e04016d0c00 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 3181 +0ms
  hci 		status = 0 +0ms
  hci 		result =  +0ms
  hci onSocketData: 016c0c00 +1ms
  hci 	event type = 1 +0ms
  hci 		cmd = 3180 +0ms
  hci 		data len = 0 +0ms
  hci onSocketData: 040e06016c0c000100 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 3180 +0ms
  hci 		status = 0 +0ms
  hci 		result = 0100 +0ms
  hci 			le = 1 +0ms
  hci 			simul = 0 +0ms
  hci onSocketData: 01091000 +1ms
  hci 	event type = 1 +0ms
  hci 		cmd = 4105 +0ms
  hci 		data len = 0 +0ms
  hci onSocketData: 040e0a01091000abb130eb27b8 +0ms
  hci 	event type = 4 +0ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 4105 +0ms
  hci 		status = 0 +0ms
  hci 		result = abb130eb27b8 +0ms
  hci address = b8:27:eb:30:b1:ab +0ms
  noble addressChange b8:27:eb:30:b1:ab +1ms
  hci onSocketData: 010c20020001 +115ms
  hci 	event type = 1 +1ms
  hci 		cmd = 8204 +0ms
  hci 		data len = 2 +0ms
  hci 			LE enable scan command +0ms
  hci 			enable scanning = false +0ms
  hci 			filter duplicates = true +0ms
  noble scanStop +0ms
  hci onSocketData: 040e04010c200c +0ms
  hci 	event type = 4 +1ms
  hci 	sub event type = 14 +0ms
  hci 		cmd = 8204 +0ms
  hci 		status = 12 +0ms

from homebridge-bluetooth.

OK, figured out the issue. But it seems like a weird one so I don't know if it was done for a reason.

Accessory.js line 119 has this.nobleAccessory = null; BUT a call to this.nobleAccessory.removeAllListeners(); seems to be needed before this.

Once this is done my pi works flawless now. Let me know if this is really a fix or if it would break something else or some other version?

Submitting a pull request with it.

from homebridge-bluetooth.

I'm not sure the null does anything either? Also, I still don't know when it connects to the device a few times and disconnects in the first place. On the mac, it connects one time so this is not an issue there.

I'm closing this for now, reopen if you do not think this works as a fix please

from homebridge-bluetooth.

Why dod you reopen?

from homebridge-bluetooth.

Sorry for the confusion, @fallenfate1982. I didn't notice your last comment 🙄

I just got back from vacation and reopened this as a reminder for myself to not forget to merge your fix into the master branch here.

from homebridge-bluetooth.

Lol ok no problem, thought I missed something.

from homebridge-bluetooth.