search

paypal / gatt

Gatt is a Go package for building Bluetooth Low Energy peripherals
BSD 3-Clause "New" or "Revised" License
1.14k stars 285 forks source link

Linux: Failed to discover services, err: invalid length #77

Closed deadprogram closed 7 years ago

deadprogram commented 8 years ago

When trying to connect to a specific peripheral under Linux, I get the error Failed to discover services, err: invalid length.

First I receive these messages:

2016/07/05 00:42:51 Request 0x02 got a mismatched response: 0x08
2016/07/05 00:42:51 ignore l2cap signal:[ 0C 00 05 00 12 01 08 00 06 00 06 00 00 00 F4 01 ]
2016/07/05 00:42:51 Request 0x10 got a mismatched response: 0x03

And then the main error:

Failed to discover services, err: invalid length

I am able to connect using Noble, so I know it is not a hardware issue per se. Also, the same gatt code works on OSX, just not Linux. Anyone else run into anything like this?

roylee17 commented 8 years ago

Thanks for reporting. Looks like the peripheral might send some l2cap signal packets. Could you paste complete log, and a hcidump for analysis?

deadprogram commented 8 years ago

Hi @roylee17 thanks for the quick response.

Here is my complete output:

$ sudo ./explorer E0:14:05:A4:3D:A9
2016/07/05 01:05:53 dev: hci0 up
2016/07/05 01:05:53 dev: hci0 reset
2016/07/05 01:05:53 dev: hci0 down
2016/07/05 01:05:53 dev: hci0 opened
State: PoweredOn
Scanning...

Peripheral ID:E0:14:05:A4:3D:A9, NAME:(Mars_143521)
  Local Name        = Mars_143521
  TX Power Level    = 0
  Manufacturer Data = [67 0 207 25 9 9 1 0]
  Service Data      = []

Connected
2016/07/05 01:05:53 Request 0x02 got a mismatched response: 0x08
2016/07/05 01:05:53 ignore l2cap signal:[ 0C 00 05 00 12 01 08 00 06 00 06 00 00 00 F4 01 ]
2016/07/05 01:05:53 Request 0x10 got a mismatched response: 0x03
[3 244 1]
Failed to discover services, err: invalid length
Disconnected
Done

Attached is my HCIDUMP file.

Thanks again! gatt-dump.txt

deadprogram commented 8 years ago

One last thing @roylee17 note that I am using the @currantlabs fork of gatt with your latest changes.

deadprogram commented 8 years ago

Hi @roylee17

Just wondering if perhaps something like you did in the ble package: https://github.com/currantlabs/ble/commit/4c151f80543a90a816a1cad3e8523ccc4671b435 might also help with this issue?

Thank you very much for your help!

deadprogram commented 8 years ago

I'd like to switch over my code to using the ble package, but I think @roylee17 you would agree it needs a little more time to stabilize. In the meantime, this issue is really blocking me at present. Any assist would be tremendously appreciated.

roylee17 commented 8 years ago

Understood. We've been using gatt as interim ble library for our project as well until the ble package made a good progress, and we made a switch.

Let's see what we can do with the gatt in the meantime.

  1. Could you uncomment the l2cap log https://github.com/currantlabs/gatt/blob/master/linux/l2cap.go#L66 https://github.com/currantlabs/gatt/blob/master/linux/l2cap.go#L121

  2. Enable timestamp for the log (added somewhere in your app flow)

    log.SetFlags(log.Lmicroseconds)
  3. and hcidump with -Xt
  4. If ble package work in this case, paste its log&hcidump for reference, otherwise, log&hcidump of noble/bleno would also help.

Thanks

deadprogram commented 8 years ago

OK, here are the files.

gatt-log.txt has the console output for the failed explorer run under gatt, with those 2 lines uncommented. gatt-dump.txt has the HCIDUMP for that same gatt explorer run

ble-log.txt has the console output for a successful explorer run under ble. ble-dump.txt has the HCIDUMP for that ble exlorer run.

Thank you VERY much! :bow: gatt-log.txt ble-log.txt ble-dump.txt gatt-dump.txt

deadprogram commented 8 years ago

Here is the output/HCIDUMP file when running using that latest commit:

$ sudo ./explorer E0:14:05:A4:3D:A9
2016/07/07 11:34:53 dev: hci0 up
2016/07/07 11:34:53 dev: hci0 reset
2016/07/07 11:34:53 dev: hci0 down
2016/07/07 11:34:53 dev: hci0 opened
State: PoweredOn
Scanning...

Peripheral ID:E0:14:05:A4:3D:A9, NAME:(Mars_143521)
  Local Name        = Mars_143521
  TX Power Level    = 0
  Manufacturer Data = [67 0 207 25 9 9 1 0]
  Service Data      = []

Connected
2016/07/07 11:34:53 Request 0x02 got a mismatched response: 0x08
2016/07/07 11:34:53 ignore l2cap signal:[ 0C 00 05 00 12 03 08 00 06 00 06 00 00 00 F4 01 ]
Service: 1800 (Generic Access)
  Characteristic  2a00 (Device Name)
    properties    read 
    value         4d6172735f313433353231 | "Mars_143521"
  Characteristic  2a01 (Appearance)
    properties    read 
    value         8000 | "\x80\x00"
  Characteristic  2a04 (Peripheral Preferred Connection Parameters)
    properties    read 
    value         0600100000000004 | "\x06\x00\x10\x00\x00\x00\x00\x04"

Service: 1801 (Generic Attribute)
  Characteristic  2a05 (Service Changed)
    properties    indicate 
Failed to subscribe characteristic, err: no cccd

Service: 9a66fa000800919111e4012d1540cb8e
2016/07/07 11:34:54 l2conn: l2cap packet is too short/corrupt, length is 3

mini-dump.txt

roylee17 commented 8 years ago

This is a different error. I pushed a change for dummy signal handling, which might help or worsen (in the later case, revert it in your test). And also add more logging stuff.

Let's try the latest commit with LOGXI=*, and hcidump with -Xt for RAW bytes and timestamps. (BTW, let's make these default settings for the bug reports)

deadprogram commented 8 years ago

Here is the output log, and HCIDUMP.

$ sudo LOGXI=* ./explorer E0:14:05:A4:3D:A9 > mini-log.txt
2016/07/07 20:03:09 dev: hci0 up
2016/07/07 20:03:09 dev: hci0 reset
2016/07/07 20:03:09 dev: hci0 down
2016/07/07 20:03:09 dev: hci0 opened
2016/07/07 20:03:10 Request 0x02 got a mismatched response: 0x08
2016/07/07 20:03:10 l2conn: short/corrupt packet, &{3585 1 3 [250 102 154]} [FA 66 9A]

mini-dump.txt mini-log.txt

roylee17 commented 8 years ago

Sorry, I missed something in the last commit, could regenerate the logs/dump ? thanks!

deadprogram commented 8 years ago

Sure here you go:

$ sudo LOGXI=* ./explorer E0:14:05:A4:3D:A9 > mini-log.txt                                                             
2016/07/07 20:42:27 dev: hci0 up
2016/07/07 20:42:27 dev: hci0 reset
2016/07/07 20:42:27 dev: hci0 down
2016/07/07 20:42:27 dev: hci0 opened
2016/07/07 20:42:28 Request 0x02 got a mismatched response: 0x08
2016/07/07 20:42:28 l2conn: short/corrupt packet, &{3585 1 3 [250 102 154]} [FA 66 9A]

mini-log.txt mini-dump.txt

roylee17 commented 8 years ago

So the previous commit didn't help at all, and messed up the logs.

But I found the problem, and let's see if the latest commit fixes it.

deadprogram commented 8 years ago

Pulled the latest changes, here is my result:

$ sudo LOGXI=* ./explorer E0:14:05:A4:3D:A9 > mini-log.txt
2016/07/07 21:45:05 dev: hci0 up
2016/07/07 21:45:05 dev: hci0 reset
2016/07/07 21:45:05 dev: hci0 down
2016/07/07 21:45:05 dev: hci0 opened
2016/07/07 21:45:06 Request 0x02 got a mismatched response: 0x08
2016/07/07 21:45:06 l2conn: short/corrupt packet, &{3585 1 3 [250 102 154]} [FA 66 9A]

Logs/dump attached. mini-dump.txt mini-log.txt

roylee17 commented 8 years ago

The logs looks like from earlier commits. I pushed some changes just few minutes before your comment.

deadprogram commented 8 years ago

OK, got the correct update, and was able to discover characteristics! Now on to the next problem ;)

I'm trying to actually communicate with a Minidrone, code works on OSX. Now that the code does not crash on Linux, it however does not actually fly.

$ sudo LOGXI=* ./minidrone Mars_143521 > mini-log.txt                                                                  
2016/07/07 22:49:42 Initializing Robot bleBot ...
2016/07/07 22:49:42 Initializing connections...
2016/07/07 22:49:42 Initializing connection ble ...
2016/07/07 22:49:42 Initializing devices...
2016/07/07 22:49:42 Initializing device drone ...
2016/07/07 22:49:42 Starting Robot bleBot ...
2016/07/07 22:49:42 Starting connections...
2016/07/07 22:49:42 Starting connection ble...
2016/07/07 22:49:42 dev: hci0 up
2016/07/07 22:49:42 dev: hci0 reset
2016/07/07 22:49:42 dev: hci0 down
2016/07/07 22:49:42 dev: hci0 opened
2016/07/07 22:49:45 Request 0x02 got a mismatched response: 0x08
2016/07/07 22:49:45 ignore l2cap signal:[ 0C 00 05 00 12 02 08 00 06 00 06 00 00 00 F4 01 ]
2016/07/07 22:49:46 Starting devices...
2016/07/07 22:49:46 Starting device drone...
2016/07/07 22:49:46 Starting work...
^C2016/07/07 22:50:00 Stopping Robot bleBot ...

Here are the log and dump files. Seems like we're almost in the air? mini-log.txt mini-dump.txt

roylee17 commented 8 years ago

Log and dump looks okay. Not sure those two failed CCCD subscriptions matter or not.

Can you try the ble package to get a side by side comparison?

deadprogram commented 8 years ago

I have a Noble-based program that runs under Linux and connects to the Minidrone, takes off, and lands.. Here is the HCIDUMP of that working.

noble-dump.txt

roylee17 commented 8 years ago

This will need some knowledge at the app level. Do you have a spec/protocol/reference for controlling the device?

deadprogram commented 8 years ago

You are correct that the 2 failed CCCD subscriptions are not the core problem, as I was able to easily determine by commenting that part of my code out.

That will also need some solution in order to receive needed updates from the minidrone.

My code for the Minidrone can be found here: https://github.com/hybridgroup/gobot/blob/feature/ble-wip/examples/minidrone.go

The Gobot driver that shows the protocol is here: https://github.com/hybridgroup/gobot/blob/feature/ble-wip/platforms/ble/ble_minidrone.go

The Gobot adaptor that makes the calls to GATT is here: https://github.com/hybridgroup/gobot/blob/feature/ble-wip/platforms/ble/ble_adaptor.go

I am able to run the minidrone.go program on OSX, so I know my overall itself is basically "correct".

One last thing, I have also attached the debug output for the Noble based code with the HCI & ATT. Seems like that is easier to look at than the just the HCIDUMP as a point of comparison.

I, and all other Linux users, seriously cannot thank you enough for your help!

noble-flight.txt

deadprogram commented 7 years ago

Hi @roylee17 just as a follow-up, the solution in my particular case, was that an explicit call to DiscoverDescriptors() was needed on Linux:

https://github.com/hybridgroup/gobot/commit/f20424feadbb00b89f62147dc44ddde9602cb6f2#diff-9150c51b8018cc8f839aa22a1ba51086R215

Thanks again for your help, I am going to close this issue to remove clutter.

roylee17 commented 7 years ago

Hi @deadprogram,

It didn't occur to me you ran into the case.

Subscription to a characteristic is actually writing a value to the characteristic's CCCD.

On OS X, its Core Bluetooth actually performs a full discovery and caches the result when it first time discovers a device. GATT is a user calls to the Core Bluetooth, so the descriptors was implicitly discovered already.

On Linux before subscribing to the a characteristic, the DiscoverDescriptors() has to be explicitly called.

The difference was a design choice, we left the discovery procedure to application. So it could performs a fast discovery if it has very specific target, or full discovery and optionally caches the results.