search

edrosten / libblepp

Modern clean C++ Bluetooth Low Energy on Linux without the Bluez DBUS API
Other
241 stars 63 forks source link

terminate called after throwing an instance of 'BLEPP::SocketConnectFailed' #37

Open moe5k opened 5 years ago

moe5k commented 5 years ago

Hi,

i got problems while connecting ...

There are no probs to connect, read etc. via bluetoothctl - tool.

info  1541687672.925407 log_fd_: Socket success: 224 (src/blestatemachine.cc)
info  1541687672.925454 log_fd_: Socket success: 269 (src/blestatemachine.cc)
info  1541687672.925480 log_fd_: Socket success: 174 (src/blestatemachine.cc)
info  1541687672.925501 log_l2cap_options: options.omtu = 672
info  1541687672.925522 log_l2cap_options: options.imtu = 672
info  1541687672.925545 log_l2cap_options: options.flush_to = 65535
info  1541687672.925565 log_l2cap_options: options.mode = 0
info  1541687672.925589 log_l2cap_options: options.fcs = 1
info  1541687672.925611 log_l2cap_options: options.max_tx = 3
info  1541687672.925633 log_l2cap_options: options.txwin_size = 63
debug 1541687672.925658 connect: address = cf:33:8f:4d:9c:3e
debug 1541687672.925679 connect: str2ba = 0
error 1541687713.911835 log_fd_: Error on line: 296 (src/blestatemachine.cc): Connection refused
terminate called after throwing an instance of 'BLEPP::SocketConnectFailed'
  what():  Connection refused
Aborted

Any suggestions?

edrosten commented 5 years ago

Have you made sure that nothing else is already connected?

If nothing was, and it's still failing to connect, can you try getting a log using hcidump or btmon for libble++ and bluetoothctl and paste them here? That should hopefully show up any discrepancies.

moe5k commented 5 years ago

Yes, I am sure there is nothing else connected. First I connect / disconnect via blutoothctl:

[bluetooth]# connect CF:33:8F:4D:9C:3E 
Attempting to connect to CF:33:8F:4D:9C:3E
[CHG] Device CF:33:8F:4D:9C:3E Connected: yes
Connection successful
[CHG] Device CF:33:8F:4D:9C:3E ServicesResolved: yes
[IMU_4d9c3e]# disconnect CF:33:8F:4D:9C:3E 
Attempting to disconnect from CF:33:8F:4D:9C:3E
[CHG] Device CF:33:8F:4D:9C:3E ServicesResolved: no
Successful disconnected
[CHG] Device CF:33:8F:4D:9C:3E Connected: no

brings the logging via btmon:

< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7  #1 [hci0] 26.447397
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Public (0x00)
        Filter policy: Ignore not in white list (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #2 [hci0] 26.448175
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #3 [hci0] 26.448269
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                 #4 [hci0] 26.450212
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 43                   #5 [hci0] 30.420352
      LE Advertising Report (0x02)
        Num reports: 1
        Event type: Connectable undirected - ADV_IND (0x00)
        Address type: Random (0x01)
        Address: CF:33:8F:4D:9C:3E (Static)
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
        RSSI: -48 dBm (0xd0)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2      #6 [hci0] 30.420474
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                 #7 [hci0] 30.428346
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25   #8 [hci0] 30.428459
        Scan interval: 60.000 msec (0x0060)
        Scan window: 60.000 msec (0x0060)
        Filter policy: White list is not used (0x00)
        Peer address type: Random (0x01)
        Peer address: CF:33:8F:4D:9C:3E (Static)
        Own address type: Public (0x00)
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                   #9 [hci0] 30.436247
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                  #10 [hci0] 30.624344
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 70
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: CF:33:8F:4D:9C:3E (Static)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x00
@ MGMT Event: Device Connected (0x000b) plen 44       {0x0005} [hci0] 30.624434
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Flags: 0x00000000
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
@ MGMT Event: Device Connected (0x000b) plen 44       {0x0002} [hci0] 30.624434
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Flags: 0x00000000
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
@ MGMT Event: Device Connected (0x000b) plen 44       {0x0001} [hci0] 30.624434
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Flags: 0x00000000
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
@ MGMT Event: Device Connected (0x000b) plen 44       {0x0004} [hci0] 30.624434
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Flags: 0x00000000
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
@ MGMT Event: Device Connected (0x000b) plen 44       {0x0003} [hci0] 30.624434
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Flags: 0x00000000
        Data length: 31
        Appearance: Unknown (0x0000)
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        128-bit Service UUIDs (complete): 1 entry
          Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
        Name (short): IMU_
< HCI Command: LE Read Remote Used.. (0x08|0x0016) plen 2  #11 [hci0] 30.624602
        Handle: 70
> ACL Data RX: Handle 70 flags 0x02 dlen 7                 #12 [hci0] 30.627649
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 247
> HCI Event: Command Status (0x0f) plen 4                  #13 [hci0] 30.628190
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12                  #14 [hci0] 30.766252
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 70
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #15 [hci0] 30.766793
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 517
< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #16 [hci0] 30.766889
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5     #17 [hci0] 30.816332
        Num handles: 1
        Handle: 70
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5     #18 [hci0] 30.866320
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 7                 #19 [hci0] 30.915635
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 247
< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #20 [hci0] 30.915899
      ATT: Read Request (0x0a) len 2
        Handle: 0x0003
> HCI Event: Number of Completed Packets (0x13) plen 5     #21 [hci0] 30.966341
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 15                #22 [hci0] 31.015659
      ATT: Read Response (0x0b) len 10
        Value: 494d555f346439633365
< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #23 [hci0] 31.015885
      ATT: Read Request (0x0a) len 2
        Handle: 0x0005
> HCI Event: Number of Completed Packets (0x13) plen 5     #24 [hci0] 31.072247
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 7                 #25 [hci0] 31.115460
      ATT: Read Response (0x0b) len 2
        Value: 0000
< ACL Data TX: Handle 70 flags 0x00 dlen 11                #26 [hci0] 31.115737
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5     #27 [hci0] 31.166336
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 18                #28 [hci0] 31.215606
      ATT: Read By Group Type Response (0x11) len 13
        Attribute data length: 6
        Attribute group list: 2 entries
        Handle range: 0x0001-0x0009
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x000a-0x000a
        UUID: Generic Attribute Profile (0x1801)
< ACL Data TX: Handle 70 flags 0x00 dlen 11                #29 [hci0] 31.215833
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x000b-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5     #30 [hci0] 31.266339
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 26                #31 [hci0] 31.315670
      ATT: Read By Group Type Response (0x11) len 21
        Attribute data length: 20
        Attribute group list: 1 entry
        Handle range: 0x000b-0xffff
        UUID: Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
@ MGMT Command: Disconnect (0x0014) plen 7            {0x0001} [hci0] 43.798716
        LE Address: CF:33:8F:4D:9C:3E (Static)
< HCI Command: Disconnect (0x01|0x0006) plen 3             #32 [hci0] 43.798791
        Handle: 70
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                  #33 [hci0] 43.800291
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4             #34 [hci0] 43.816289
        Status: Success (0x00)
        Handle: 70
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Command Complete (0x0001) plen 10       {0x0001} [hci0] 43.816365
      Disconnect (0x0014) plen 7
        Status: Success (0x00)
        LE Address: CF:33:8F:4D:9C:3E (Static)
@ MGMT Event: Device Disconnected (0x000c) plen 8     {0x0005} [hci0] 43.816383
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Reason: Connection terminated by local host (0x02)
@ MGMT Event: Device Disconnected (0x000c) plen 8     {0x0002} [hci0] 43.816383
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Reason: Connection terminated by local host (0x02)
@ MGMT Event: Device Disconnected (0x000c) plen 8     {0x0004} [hci0] 43.816383
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Reason: Connection terminated by local host (0x02)
@ MGMT Event: Device Disconnected (0x000c) plen 8     {0x0003} [hci0] 43.816383
        LE Address: CF:33:8F:4D:9C:3E (Static)
        Reason: Connection terminated by local host (0x02)

After that I try connecting using the libblepp ...

info  1542006297.266721 log_fd_: Socket success: 224 (src/blestatemachine.cc)
info  1542006297.266830 log_fd_: Socket success: 269 (src/blestatemachine.cc)
info  1542006297.266893 log_fd_: Socket success: 174 (src/blestatemachine.cc)
info  1542006297.266933 log_l2cap_options: options.omtu = 672
info  1542006297.266974 log_l2cap_options: options.imtu = 672
info  1542006297.267020 log_l2cap_options: options.flush_to = 65535
info  1542006297.267066 log_l2cap_options: options.mode = 0
info  1542006297.267112 log_l2cap_options: options.fcs = 1
info  1542006297.267157 log_l2cap_options: options.max_tx = 3
info  1542006297.267190 log_l2cap_options: options.txwin_size = 63
debug 1542006297.267231 connect: address = CF:33:8F:4D:9C:3E
debug 1542006297.267277 connect: str2ba = 0
error 1542006337.655835 log_fd_: Error on line: 296 (src/blestatemachine.cc): Connection refused
terminate called after throwing an instance of 'BLEPP::SocketConnectFailed'
  what():  Connection refused
Aborted (core dumped)

and receive the following out put from btmon:

< HCI Command: LE Remove Device F.. (0x08|0x0012) plen 7  #35 [hci0] 199.267381
        Address type: Random (0x01)
        Address: CF:33:8F:4D:9C:3E (Static)
> HCI Event: Command Complete (0x0e) plen 4               #36 [hci0] 199.268828
      LE Remove Device From White List (0x08|0x0012) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Add Device To W.. (0x08|0x0011) plen 7  #37 [hci0] 199.268914
        Address type: Public (0x00)
        Address: CF:33:8F:4D:9C:3E (OUI CF-33-8F)
> HCI Event: Command Complete (0x0e) plen 4               #38 [hci0] 199.269836
      LE Add Device To White List (0x08|0x0011) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Parame.. (0x08|0x000b) plen 7  #39 [hci0] 199.269877
        Type: Passive (0x00)
        Interval: 60.000 msec (0x0060)
        Window: 30.000 msec (0x0030)
        Own address type: Public (0x00)
        Filter policy: Ignore not in white list (0x01)
> HCI Event: Command Complete (0x0e) plen 4               #40 [hci0] 199.270836
      LE Set Scan Parameters (0x08|0x000b) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2    #41 [hci0] 199.270875
        Scanning: Enabled (0x01)
        Filter duplicates: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4               #42 [hci0] 199.271837
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2    #43 [hci0] 239.687687
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4               #44 [hci0] 239.688978
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
edrosten commented 5 years ago

OK thanks. I'm going to set aside some time to really pore over the logs. Haven't had time yet.

dylanetaft commented 5 years ago

Do you have two Bluetooth adapters in your machine? bluetoothctl list will show.

dylanetaft commented 5 years ago

This is gonna be one of 3 things I bet.
1) Two+ BT adapters, a BT4 incapable device is being used because the right one hasn't been specified. 2) moe5k: https://github.com/edrosten/libblepp/blob/master/src/blestatemachine.cc Line 278, 279 Can you edit your local source, switch from if (pubaddr) addr.l2_bdaddr_type = BDADDR_LE_PUBLIC; else addr.l2_bdaddr_type = BDADDR_LE_RANDOM;

to addr.l2_bdaddr_type = BDADDR_LE_RANDOM; And try again?

3) Somehow use of a different L2CAP Channel is required

moe5k commented 5 years ago
  1. No, there is definitely just one adapter installed.
  2. of course I can try that but at the moment I am in a hospital. I have not the right hardware here for checking the result. but I will do in approx. 2 weeks and will let you know.
nikola-rusev commented 5 years ago

Hello all, and happy new year! I wanted to ask if you have managed to resolve this issue. I too have encountered the exact same problem and haven't been able to fix it. Any info would be much appreciated. Thanks!

edrosten commented 5 years ago

Hi,

Sorry I've not had a chance to fix this yet: my day job got super busy. I should be able to take a look soon. Feel free to bug me if I forget!

-Ed

On Thu, 3 Jan 2019 at 09:49, nikola-rusev notifications@github.com wrote:

Hello all, and happy new year! I wanted to ask if you have managed to resolve this issue. I too have encountered the exact same problem and haven't been able to fix it. Any info would be much appreciated. Thanks!

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/edrosten/libblepp/issues/37#issuecomment-451096556, or mute the thread https://github.com/notifications/unsubscribe-auth/ABGW64zetHl_MHUpFqH9RSrW0Wfr902sks5u_dI4gaJpZM4YUyX9 .

moe5k commented 5 years ago

I decided to use the tinyb - Lib instead ...

edrosten commented 5 years ago

Hi,

I had another look through (wow tracing bluetooth packet dumps by hand is fun!) and I think you might not be disabling the scan before connection. If either of you are still using the lib could you try stopping the scan after you've found a device but before trying to connect?

-Ed

On Fri, 4 Jan 2019 at 10:57, moe5k notifications@github.com wrote:

I decided to use the tinyb - Lib instead ...

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/edrosten/libblepp/issues/37#issuecomment-451413747, or mute the thread https://github.com/notifications/unsubscribe-auth/ABGW62JwFGZEZmc1Jem0XZQkTn7PB2BKks5u_zOtgaJpZM4YUyX9 .

nikola-rusev commented 5 years ago

Hello,

I've tried starting another scan while one is already running, that always produces the error. Strangely enough, the problem manifests itself only from time to time now and I can't make out a pattern or deduce the reason. I'll make it explicitly stop the scan before connecting and get back to you in a couple of days with the results, as these days i'm occupied with other stuff.

Thanks for the input!

danergo commented 5 days ago

Folks, sorry for giving some ups to this issue. But something got my attention here:

Remote end asks us to raise the MTU to 247:

> ACL Data RX: Handle 70 flags 0x02 dlen 7                 #12 [hci0] 30.627649
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 247

Then we reply him with a completely different MTU??:

< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #15 [hci0] 30.766793
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 517

Even worse, we request him to re-raise his MTU:

< ACL Data TX: Handle 70 flags 0x00 dlen 7                 #16 [hci0] 30.766889
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517