Raspberry Pi 3 UART BT LE Reconnects not working...

[robotastic]

Any idea why there would be a problem with the built in BT chip on the Raspberry Pi 3? I am able to do an initial BT LE Pairing and have an encrypted connection setup correctly. However, after I break the connection and reconnect, the connection will not stay up. Judging by the HCIDump, the encryption is reestablished fine and some initial data packets are able to go back and forth correctly, however after about 2 seconds of being idle the connection drops.

I have it working fine on the same raspberry Pi using a BroadComm USB Dongle. The RPI 3 bluetooth is also a BroadComm chip connected over UART. The only obvious difference I can see is that the internal Bluetooth is v4.1 and the USB Dongle is v4.0.

From HCIDump it looks like it is the Pi initiating the disconnect:

2016-04-10 11:08:47.039373 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0001, end 0x0005
      type-uuid 0x2a00
2016-04-10 11:08:47.042228 < ACL data: handle 64 flags 0x00 dlen 16
    ATT: Read By Type resp (0x09)
      length: 10
        handle 0x0003, value 0x62 0x6c 0x65 0x2d 0x61 0x6e 0x63 0x73 
2016-04-10 11:08:47.285530 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 1
2016-04-10 11:08:48.953332 < HCI Command: Disconnect (0x01|0x0006) plen 3
    handle 64 reason 0x13
    Reason: Remote User Terminated Connection
2016-04-10 11:08:48.953737 > HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
2016-04-10 11:08:49.020318 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 64 reason 0x16
    Reason: Connection Terminated by Local Host

[sandeepmistry]

@robotastic please make sure you are using the latest 0.4.3 release. This has been resolved by 4bcafd6. See discussion in noble/bleno#180.

Let me know if you think it is unrelated to the above.

[robotastic]

I double checked and I am running v0.4.3. I erased the node_modules dir and reinstalled to be sure.
I think it maybe unrelated. I am able to do the initial pairing fine using the UART BTLE on the RPI 3. I get a stable connection for this initial connection that does not drop. I am doing this pairing from an iPhone and it is connecting using ANCS. After I confirm the pairing dialog on the iPhone, the RPI is listed under My Devices. If I go out of range or turn the bluetooth off and then on, on the iphone, there are the issues I listed above with reconnecting a paired link. It is really weird, since the link seems to be re-encrypting fine. After it disconnects, it will just start reconnecting again and endlessly loop like this.

Reconnecting a paired link works perfectly fine when I use a USB BT Dongle. Anything else I can try?

My code is up here: https://github.com/robotastic/ble-ancs

Here is a larger snippet of the HCIDump for more context, this is after the initial pairing and a disconnect:

2016-04-10 11:08:44.720895 > HCI Event: LE Meta Event (0x3e) plen 19
    LE Connection Complete
      status 0x00 handle 64, role slave
      bdaddr 41:FF:03:8C:BA:AF (Random)
2016-04-10 11:08:44.721183 < HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2
  40 00 
2016-04-10 11:08:44.722776 > HCI Event: Command Status (0x0f) plen 4
    LE Read Remote Used Features (0x08|0x0016) status 0x00 ncmd 1
2016-04-10 11:08:44.723198 < HCI Command: LE Create Connection (0x08|0x000d) plen 25
    bdaddr 41:FF:03:8C:BA:AF type 1
    interval 96 window 48 initiator_filter 0
    own_bdaddr_type 0 min_interval 40 max_interval 56
    latency 0 supervision_to 42 min_ce 0 max_ce 0
2016-04-10 11:08:44.723995 > HCI Event: Command Status (0x0f) plen 4
    LE Create Connection (0x08|0x000d) status 0x00 ncmd 1
2016-04-10 11:08:44.724313 > HCI Event: LE Meta Event (0x3e) plen 19
    LE Connection Complete
      status 0x0b handle 64, role slave
      bdaddr 41:FF:03:8C:BA:AF (Random)
2016-04-10 11:08:44.813326 < ACL data: handle 64 flags 0x00 dlen 7
    ATT: MTU req (0x02)
      client rx mtu 256
2016-04-10 11:08:44.830733 > HCI Event: LE Meta Event (0x3e) plen 13
    LE Long Term Key Request
    40 00 98 34 9B 4D B3 DE 34 0D C2 9F 
2016-04-10 11:08:44.830765 < HCI Command: LE Long Term Key Request Reply (0x08|0x001a) plen 18
  40 00 9D CE C5 37 2A EC 2E AF 9B 3F BA 46 8A 34 57 5F 
2016-04-10 11:08:44.831523 > HCI Event: Command Complete (0x0e) plen 6
    LE Long Term Key Request Reply (0x08|0x001a) ncmd 1
    00 40 00 
2016-04-10 11:08:44.950953 > HCI Event: Encrypt Change (0x08) plen 4
    status 0x00 handle 64 encrypt 0x01
2016-04-10 11:08:44.951010 < ACL data: handle 64 flags 0x00 dlen 16
    L2CAP(d): cid 0x0005 len 12 [psm 0]
      12 01 08 00 28 00 38 00 00 00 48 00 
2016-04-10 11:08:45.040758 > HCI Event: LE Meta Event (0x3e) plen 12
    LE Read Remote Used Features Complete
      status 0x00 handle 64
      Features: 0x1f 0x00 0x00 0x00 0x00 0x00 0x00 0x00
2016-04-10 11:08:45.042033 > ACL data: handle 64 flags 0x02 dlen 7
    ATT: MTU req (0x02)
      client rx mtu 158
2016-04-10 11:08:45.042159 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.042759 > ACL data: handle 64 flags 0x02 dlen 27
2016-04-10 11:08:45.043645 > ACL data: handle 64 flags 0x01 dlen 27
2016-04-10 11:08:45.043925 > ACL data: handle 64 flags 0x01 dlen 9
    L2CAP(d): cid 0x003a len 59 [psm 0]
      01 39 02 14 01 00 02 0F 63 6F 6D 2E 61 70 70 6C 65 2E 42 54 
      2E 54 53 01 22 02 00 01 1D 63 6F 6D 2E 61 70 70 6C 65 2E 42 
      54 4C 45 53 65 72 76 65 72 2E 63 6C 61 73 73 69 63 00 01 
2016-04-10 11:08:45.045791 < ACL data: handle 64 flags 0x00 dlen 7
    ATT: MTU resp (0x03)
      server rx mtu 158
2016-04-10 11:08:45.070617 > ACL data: handle 64 flags 0x02 dlen 11
    L2CAP(d): cid 0x003a len 7 [psm 0]
      09 05 01 00 00 00 00 
2016-04-10 11:08:45.130587 > ACL data: handle 64 flags 0x02 dlen 7
    ATT: MTU resp (0x03)
      server rx mtu 158
2016-04-10 11:08:45.131265 > ACL data: handle 64 flags 0x02 dlen 10
    L2CAP(d): cid 0x0005 len 6 [psm 0]
      13 01 02 00 00 00 
2016-04-10 11:08:45.131812 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Group req (0x10)
      start 0x0001, end 0xffff
      type-uuid 0x2800
2016-04-10 11:08:45.134289 < ACL data: handle 64 flags 0x00 dlen 27
    ATT: Find By Type req (0x06)
      start 0x0001, end 0xffff, uuid 0x2800
      value 0xd0 0x00 0x2d 0x12 0x1e 0x4b 0x0f 0xa4 0x99 0x4e 0xce 0xb5 0x31 0xf4 0x05 0x79
2016-04-10 11:08:45.142169 < ACL data: handle 64 flags 0x00 dlen 18
    ATT: Read By Group resp (0x11)
      attr handle 0x0001, end group handle 0x0005
      value 0x00 0x18
      attr handle 0x0006, end group handle 0x0009
      value 0x01 0x18
2016-04-10 11:08:45.161467 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.190657 > ACL data: handle 64 flags 0x02 dlen 9
    ATT: Find By Type resp (0x07)
      Found attr 0x001e, group end handle 0x0027
2016-04-10 11:08:45.191184 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Group req (0x10)
      start 0x000a, end 0xffff
      type-uuid 0x2800
2016-04-10 11:08:45.196733 < ACL data: handle 64 flags 0x00 dlen 11
    ATT: Read By Type req (0x08)
      start 0x001e, end 0x0027
      type-uuid 0x2803
2016-04-10 11:08:45.201962 < ACL data: handle 64 flags 0x00 dlen 26
    ATT: Read By Group resp (0x11)
      attr handle 0x000a, end group handle 0x000e
      value 0x37 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x33 0x13
2016-04-10 11:08:45.221132 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.251085 > ACL data: handle 64 flags 0x02 dlen 27
2016-04-10 11:08:45.251786 > ACL data: handle 64 flags 0x01 dlen 27
2016-04-10 11:08:45.252248 > ACL data: handle 64 flags 0x01 dlen 15
    ATT: Read By Type resp (0x09)
      length: 21
        handle 0x001f, value 0x88 0x20 0x00 0xd9 0xd9 0xaa 0xfd 0xbd 0x9b 0x21 0x98 0xa8 0x49 0xe1 0x45 0xf3 0xd8 0xd1 0x69 
        handle 0x0022, value 0x10 0x23 0x00 0xbd 0x1d 0xa2 0x99 0xe6 0x25 0x58 0x8c 0xd9 0x42 0x01 0x63 0x0d 0x12 0xbf 0x9f 
        handle 0x0025, value 0x10 0x26 0x00 0xfb 0x7b 0x7c 0xce 0x6a 0xb3 0x44 0xbe 0xb5 0x4b 0xd6 0x24 0xe9 0xc6 0xea 0x22 
2016-04-10 11:08:45.252653 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Group req (0x10)
      start 0x000f, end 0xffff
      type-uuid 0x2800
2016-04-10 11:08:45.260199 < ACL data: handle 64 flags 0x00 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0027, end 0x0027
      type-uuid 0x2803
2016-04-10 11:08:45.264786 < ACL data: handle 64 flags 0x00 dlen 9
    ATT: Error (0x01)
      Error: Attribute not found (10)
      Read By Group req (0x10) on handle 0x000f
2016-04-10 11:08:45.281127 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.310657 > ACL data: handle 64 flags 0x02 dlen 9
    ATT: Error (0x01)
      Error: Attribute not found (10)
      Read By Type req (0x08) on handle 0x0027
2016-04-10 11:08:45.311182 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0006, end 0x0009
      type-uuid 0x2803
2016-04-10 11:08:45.319455 < ACL data: handle 64 flags 0x00 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0022, end 0x0024
      type-uuid 0x2902
2016-04-10 11:08:45.323820 < ACL data: handle 64 flags 0x00 dlen 13
    ATT: Read By Type resp (0x09)
      length: 7
        handle 0x0007, value 0x20 0x08 0x00 0x05 0x2a 
2016-04-10 11:08:45.341127 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.370677 > ACL data: handle 64 flags 0x02 dlen 10
    ATT: Read By Type resp (0x09)
      length: 4
        handle 0x0024, value 0x00 0x00 
2016-04-10 11:08:45.371188 > ACL data: handle 64 flags 0x02 dlen 9
    ATT: Find Information req (0x04)
      start 0x0009, end 0x0009
2016-04-10 11:08:45.374278 < ACL data: handle 64 flags 0x00 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0025, end 0x0027
      type-uuid 0x2902
2016-04-10 11:08:45.377594 < ACL data: handle 64 flags 0x00 dlen 10
    ATT: Find Information resp (0x05)
      format: uuid-16
        handle 0x0009, uuid 0x2902 (GATT(desc) Client Characteristic Configuration)
2016-04-10 11:08:45.401129 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.479425 > ACL data: handle 64 flags 0x02 dlen 10
    ATT: Read By Type resp (0x09)
      length: 4
        handle 0x0027, value 0x00 0x00 
2016-04-10 11:08:45.479938 > ACL data: handle 64 flags 0x02 dlen 9
    ATT: Write req (0x12)
      handle 0x0009 value  0x02 0x00
2016-04-10 11:08:45.480437 > HCI Event: LE Meta Event (0x3e) plen 10
    LE Connection Update Complete
      status 0x00 handle 64
      interval 60.00ms, latency 0.00ms, superv. timeout 720.00ms
2016-04-10 11:08:45.483110 < ACL data: handle 64 flags 0x00 dlen 9
    ATT: Write req (0x12)
      handle 0x0024 value  0x01 0x00
2016-04-10 11:08:45.485980 < ACL data: handle 64 flags 0x00 dlen 5
    ATT: Write resp (0x13)
2016-04-10 11:08:45.539863 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.599333 > ACL data: handle 64 flags 0x02 dlen 5
    ATT: Write resp (0x13)
2016-04-10 11:08:45.600028 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x1d 0x02 0x01 0x00 0x00 0x00 0x00 
2016-04-10 11:08:45.600642 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x1d 0x02 0x02 0x01 0x00 0x00 0x00 
2016-04-10 11:08:45.601271 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x1d 0x02 0x03 0x02 0x00 0x00 0x00 
2016-04-10 11:08:45.601873 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x1d 0x02 0x04 0x03 0x00 0x00 0x00 
2016-04-10 11:08:45.602489 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x1d 0x02 0x05 0x04 0x00 0x00 0x00 
2016-04-10 11:08:45.602597 < ACL data: handle 64 flags 0x00 dlen 9
    ATT: Write req (0x12)
      handle 0x0027 value  0x01 0x00
2016-04-10 11:08:45.659489 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x15 0x06 0x01 0x05 0x00 0x00 0x00 
2016-04-10 11:08:45.660451 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x10 0x00 0x01 0x06 0x00 0x00 0x00 
2016-04-10 11:08:45.660488 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 2
2016-04-10 11:08:45.660833 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x15 0x00 0x02 0x07 0x00 0x00 0x00 
2016-04-10 11:08:45.661437 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x15 0x00 0x03 0x08 0x00 0x00 0x00 
2016-04-10 11:08:45.662053 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x15 0x06 0x02 0x09 0x00 0x00 0x00 
2016-04-10 11:08:45.662655 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x10 0x00 0x04 0x0a 0x00 0x00 0x00 
2016-04-10 11:08:45.719489 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x15 0x06 0x03 0x0b 0x00 0x00 0x00 
2016-04-10 11:08:45.720117 > ACL data: handle 64 flags 0x02 dlen 15
    ATT: Handle notify (0x1b)
      handle 0x0023
      value 0x00 0x10 0x00 0x05 0x0c 0x00 0x00 0x00 
2016-04-10 11:08:45.720528 > ACL data: handle 64 flags 0x02 dlen 5
    ATT: Write resp (0x13)
2016-04-10 11:08:47.039373 > ACL data: handle 64 flags 0x02 dlen 11
    ATT: Read By Type req (0x08)
      start 0x0001, end 0x0005
      type-uuid 0x2a00
2016-04-10 11:08:47.042228 < ACL data: handle 64 flags 0x00 dlen 16
    ATT: Read By Type resp (0x09)
      length: 10
        handle 0x0003, value 0x62 0x6c 0x65 0x2d 0x61 0x6e 0x63 0x73 
2016-04-10 11:08:47.285530 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 64 packets 1
2016-04-10 11:08:48.953332 < HCI Command: Disconnect (0x01|0x0006) plen 3
    handle 64 reason 0x13
    Reason: Remote User Terminated Connection
2016-04-10 11:08:48.953737 > HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
2016-04-10 11:08:49.020318 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 64 reason 0x16
    Reason: Connection Terminated by Local Host
2016-04-10 11:08:49.083515 < HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1
  01 
2016-04-10 11:08:49.085210 > HCI Event: Command Complete (0x0e) plen 4
    LE Set Advertise Enable (0x08|0x000a) ncmd 1
    status 0x00

[sandeepmistry]

This is happening because the kernel is going down a different path than the USB adapter:

2016-04-10 11:08:44.721183 < HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2
  40 00 
2016-04-10 11:08:44.722776 > HCI Event: Command Status (0x0f) plen 4
    LE Read Remote Used Features (0x08|0x0016) status 0x00 cmd 1

because LE Read Remote Used Features is not supported in the adapter. You'll have to figure another workaround, to prevent the kernel from disconnecting things.

[sandeepmistry]

This should be fixed by c5d7f84, plus there is also #39 that has some re-working to try.