gattlib icon indicating copy to clipboard operation
gattlib copied to clipboard

gattlib_connect does not succeed all the time when it should

Open cryptax opened this issue 8 years ago • 16 comments
trafficstars

I wrote a program using gattlib that connects to a BLE device. Unfortunately, although the device is in a correct state, the connection fails many times before it eventually works. I consequently have to perform several connection attemps before I actually manage to connect.

This issue does not occur when I use gatttool: I always connect (perhaps sometimes a bit longer) provided my device/host/dongle is in a normal state of course.

That's the piece of code I use for connection:

gatt_connection = gattlib_connect(NULL, addr, BDADDR_LE_RANDOM, BT_IO_SEC_LOW, 0, 0);
if(gatt_connection == NULL){
  printf("[-] Connection failed\n");

Sample output of my program:

[>>>] Connecting to xx:xx:xx:xx:xx:xx... (attempt no=1)
[-] Connection failed
[>>>] Trying again...
[>>>] Connecting to xx:xx:xx:xx:xx:xx... (attempt no=2)
[+] Connected to xx:xx:xx:xx:xx:xx

Why is that? Is there a way I can change some settings etc so that the connection always succeeds (provided the device is there ;)?

For example, with gatttool:

$ gatttool -I -b xx:xx:xx:xx:xx:xx -t random
[xx:xx:xx:xx:xx:xx][LE]> connect
Attempting to connect to xx:xx:xx:xx:xx:xx
Connection successful
[xx:xx:xx:xx:xx:xx][LE]>

I have bluez 5.37 and the latest checkout of gattlib.

cryptax avatar Dec 08 '16 14:12 cryptax

@cryptax I have just added proper Bluez5 support (based on Bluez 5.43). I would be curious to know whether you still have the issue. gattlib_connect() has a 6 seconds timeout. How long gatttool takes to connect to your device?

oliviermartin avatar Jan 31 '17 21:01 oliviermartin

I experience something similar. Often the connects fails, but when it succeeds a GLib_Warning is also printed (gattlib-master as of 2017-02-11, on RaspberryPi3, BlueZ 5.43).

E.g.

./read_write 20:CD:39:B1:8E:E3 read "00002a19-0000-1000-8000-00805f9b34fb" Read UUID completed: 57

(process:3406): GLib-WARNING **: Invalid file descriptor.

./read_write 20:CD:39:B1:8E:E3 read "00002a19-0000-1000-8000-00805f9b34fb" Fail to connect to the bluetooth device.

(Sometimes the read just 'hangs' foever after having printed the read value...)

stepen avatar Feb 11 '17 10:02 stepen

I know about the warning. It should be harmless even if I am planning to fix it at some point.

Does gatttool provided by your RaspberryPi is also slow? I am wondering if the slowness issue really comes from gattlib or just the BLE device itself. There is a possibility to increase the timeout by changing CONNECTION_TIMEOUT in https://github.com/labapart/gattlib/blob/master/src/gattlib_connect.c#L39 The timeout is actually a 2 seconds.

oliviermartin avatar Feb 11 '17 14:02 oliviermartin

I'll try to experiment with the 2s timeout. Here's some additional data.

//Using (built-in) gattool (huge variation in response times, but always reports back - large response times could easily be a problem with the device/Adapter) $ sudo hciconfig hci0 down; sudo hciconfig hci0 up $ time gatttool -b 20:CD:39:B1:8E:E3 --char-read -a 0x0040 Characteristic value/descriptor: 4f

real 0m0.409s user 0m0.000s sys 0m0.000s

... 7 subsequent calls:
real 0m4.247s real 0m2.099s real 0m3.855s real 0m1.689s real 0m5.221s real 0m1.978s real 0m5.227s


// Using gatlib (Many fails, could very well be related to the 2s timeout) $ sudo hciconfig hci0 down; sudo hciconfig hci0 up $ time ./read_write 20:CD:39:B1:8E:E3 read "00002a19-0000-1000-8000-00805f9b34fb" Read UUID completed: 4f

(process:30282): GLib-WARNING **: Invalid file descriptor.

real 0m1.715s user 0m1.710s sys 0m0.000s

... 5 subsequent calls: real 0m6.763s // Fail to connect to the bluetooth device. real 0m6.155s // Fail to connect to the bluetooth device. real 0m1.886s // Read UUID completed: 4f real 0m6.307s // Fail to connect to the bluetooth device real 0m0.007s // connect: Device or resource busy (16), Error: gattlib_connect - initialization, Fail to connect to the bluetooth device. [Never recovers from this until 'hciconfig down/up' is executed]

stepen avatar Feb 11 '17 18:02 stepen

Tried to change the CONNECTION_TIMEOUT to 6 (and rebuild), provided the same 'picture' as before.. with many connection-fails, just with a longer timeout period (~CONN_TIMEOUT+4)

$ sudo hciconfig hci0 down; sudo hciconfig hci0 up $ time ./read_write 20:CD:39:B1:8E:E3 read "00002a19-0000-1000-8000-00805f9b34fb" Read UUID completed: 4d

(process:30476): GLib-WARNING **: Invalid file descriptor.

real 0m0.429s user 0m0.410s sys 0m0.010s

Subsequent calls: real 0m2.115s //Read UUID completed: 4d real 0m10.493s //Fail to connect to the bluetooth device. real 0m10.620s //Fail to connect to the bluetooth device. real 0m1.719s //Read UUID completed: 4d real 0m10.109s //Fail to connect to the bluetooth device. real 0m10.574s //Fail to connect to the bluetooth device. real 0m10.758s //Fail to connect to the bluetooth device. real 0m10.126s //Fail to connect to the bluetooth device. real 0m10.262s //Fail to connect to the bluetooth device. real 0m10.431s //Fail to connect to the bluetooth device.

(I also did 10 calls with gatttool, and none failed. Timing was avg. < 1.1s)

Finally changing the CONNECTION_TIMEOUT to 12 just resulted in failed connects after ~16s (Pattern was again the same. First connect is often OK, subsequent calls fail except a few)

stepen avatar Feb 11 '17 18:02 stepen

As I told stepen in another issue I have just fixed GLib_Warning in https://github.com/labapart/gattlib/commit/ed3ff0627f8d60f54c2afd602bb8b68a8e1ca02b.

oliviermartin avatar Feb 18 '17 16:02 oliviermartin

@stepen , do you mind doing the same test with the ported gatttool. The gatttool example in the project gattlib (https://github.com/labapart/gattlib/tree/master/examples/gatttool) is the same version of the builtin gatttool but with gattlib calls.

time ./gatttool -b 20:CD:39:B1:8E:E3 --char-read -a 0x0040

oliviermartin avatar Feb 18 '17 16:02 oliviermartin

With this following source file I have almost 100% success (I have not tried write). I replaced gattlib_connect by gattlib_connect_async. I guess the issue is in gattlib_connect.

/*
 *
 *  GattLib - GATT Library
 *
 *  Copyright (C) 2016-2017  Olivier Martin <[email protected]>
 *
 *
 *  This program is free software; you can redistribute it and/or modify
 *  it under the terms of the GNU General Public License as published by
 *  the Free Software Foundation; either version 2 of the License, or
 *  (at your option) any later version.
 *
 *  This program is distributed in the hope that it will be useful,
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *  GNU General Public License for more details.
 *
 *  You should have received a copy of the GNU General Public License
 *  along with this program; if not, write to the Free Software
 *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 *
 */

#include <assert.h>
#include <stdbool.h>
#include <stdio.h>
#include <stdlib.h>

#include "gattlib.h"

typedef enum { READ, WRITE} operation_t;
operation_t g_operation;

static uuid_t g_uuid;
long int value_data;

static void usage(char *argv[]) {
	printf("%s <device_address> <read|write> <uuid> [<hex-value-to-write>]\n", argv[0]);
}

volatile bool g_operation_completed;
static void connect_cb(gatt_connection_t* connection) {
	if (connection != NULL) {
		uint8_t buffer[100];
		int len, i, ret;

		if (g_operation == READ) {
			len = gattlib_read_char_by_uuid(connection, &g_uuid, buffer, sizeof(buffer));

			printf("Read UUID completed: ");
			for (i = 0; i < len; i++)
				printf("%02x ", buffer[i]);
			printf("\n");
		} else {
			uint16_t handle = 0; //TODO: FIXME
			ret = gattlib_write_char_by_handle(connection, handle, buffer, sizeof(buffer));
			assert(ret == 0);
		}
	}
	g_operation_completed = true;
}

int main(int argc, char *argv[]) {
	gatt_connection_t* connection;

	if ((argc != 4) && (argc != 5)) {
		usage(argv);
		return 1;
	}

	if (strcmp(argv[2], "read") == 0) {
		g_operation = READ;
	} else if ((strcmp(argv[2], "write") == 0) && (argc == 5)) {
		g_operation = WRITE;

		if ((strlen(argv[4]) >= 2) && (argv[4][0] == '0') && (argv[4][0] == 'x')) {
			value_data = strtol(argv[4], NULL, 0);
		} else {
			value_data = strtol(argv[4], NULL, 16);
		}
		printf("Value to write: 0x%lx\n", value_data);
	} else {
		usage(argv);
		return 1;
	}

	if (gattlib_string_to_uuid(argv[3], strlen(argv[3]) + 1, &g_uuid) < 0) {
		usage(argv);
		return 1;
	}

	int n;
	for (n=0; n<1000; n++) {
		printf("* Connection %d\n", n);
		g_operation_completed = false;
		connection = gattlib_connect_async(NULL, argv[1], BDADDR_LE_RANDOM, BT_SEC_LOW, 0, 0, connect_cb);
		if (connection == NULL) {
			fprintf(stderr, "Fail to connect to the bluetooth device.\n");
			return 1;
		} else {
			while (!g_operation_completed);
			gattlib_disconnect(connection);
		}
	}
	return 0;
}

oliviermartin avatar Feb 18 '17 18:02 oliviermartin

Here is some additional data.

Run #1: NEW gattlib-gatttool, Device=20:CD:39:B1:8E:E3: 59 calls, 9 fail-to-read, 3 resource busy. Run #2: NEW gattlib-gatttool, Device=20:CD:39:B1:8E:E3: (with CONNECTION_TIMEOUT=4s): 10 calls, 1 fail-to-read, 4 resource busy. Run #3: ORIGINAL gatttool, Device=20:CD:39:B1:8E:E3 (BlueZ, 5.23): 69 calls: 0 failed-to-read, 0 resource busy Run #4: NEW gattlib-gatttool: Different Device (a kitchen termometer): 52 calls, 0 failed-to-read, 0 resource busy.

I've only included data for run #1 and run#2. And as I said earliere, it MIGHT well be a problem with the actual device (20:CD:39:B1:8E:E3=prototype), which the results partly hints at.

RUN #1

$ time ./gatttool -b 20:CD:39:B1:8E:E3 --char-read -a 0x0040
Characteristic value/descriptor: 5a

real    0m1.660s  // OK
user    0m0.000s
sys     0m0.010s

Subsequent:

real    0m0.147s  // OK
real    0m0.113s  // OK
real    0m0.131s  // OK
real    0m0.130s  // OK
real    0m0.095s  // OK
real    0m0.110s  // OK
real    0m0.143s  // OK
real    0m0.105s  // OK
real    0m0.106s  // OK
real    0m0.114s  // OK
real    0m0.093s  // OK
real    0m0.111s  // OK
real    0m0.129s  // OK
real    0m0.130s  // OK
real    0m0.148s  // OK
real    0m0.152s  // OK
real    0m0.119s  // OK
real    0m0.113s  // FAILED - nothing is read
real    0m2.012s  // FAILED - nothing is read
real    0m2.012s  // FAILED - nothing is read
real    0m2.006s  // FAILED - nothing is read
real    0m2.012s  // FAILED - nothing is read
real    0m2.014s  // OK
real    0m0.115s  // OK
real    0m0.130s  // OK
real    0m0.128s  // OK
real    0m0.130s  // OK
real    0m0.157s  // OK
real    0m0.096s  // OK
real    0m0.098s  // OK
real    0m0.223s  // OK
real    0m0.136s  // OK
real    0m0.099s  // OK
real    0m0.138s  // OK
real    0m0.120s  // OK
real    0m0.091s  // OK
real    0m0.149s  // OK
real    0m2.011s  // FAILED - nothing is read
real    0m2.011s  // FAILED - nothing is read
real    0m1.872s  // OK
real    0m0.108s  // OK
real    0m0.113s  // OK
real    0m0.135s  // OK
real    0m0.106s  // OK
real    0m0.153s  // OK
real    0m0.096s  // OK
real    0m0.108s  // OK
real    0m0.130s  // OK
real    0m0.148s  // OK
real    0m0.113s  // OK
real    0m0.139s  // OK
real    0m0.129s  // OK
real    0m0.139s  // OK
real    0m2.009s  // FAILED - nothing is read
real    0m2.011s  // FAILED - nothing is read
real    0m0.014s  // FAILED - connect: Device or resource busy (16)
real    0m0.014s  // FAILED - connect: Device or resource busy (16)
real    0m0.013s  // FAILED - connect: Device or resource busy (16)

Never recovers from this. 'bluetoothctl' (info 20:CD:39:B1:8E:E3) reports device as 'connected = yes'. Which explains the error, but not why it occured in the first place. I waited 20 min to see if it would time out or something, but it did not. 'Resource busy' persisted. Only resolution is to either turn the device off and restart or disconnect via 'bluetoothctr'.

RUN #2

$ time ./gatttool -b 20:CD:39:B1:8E:E3 --char-read -a 0x0040
Characteristic value/descriptor: 57

real    0m1.645s
user    0m0.000s
sys     0m0.010s

Subsequent

real    0m3.691s  // OK
real    0m0.099s  // OK
real    0m0.140s  // OK
real    0m0.102s  // OK
real    0m4.049s  // OK - Failed to read
real    0m0.013s  // FAILED - connect: Device or resource busy (16)
real    0m0.013s  // FAILED - connect: Device or resource busy (16)
real    0m0.014s  // FAILED - connect: Device or resource busy (16)
real    0m0.013s  // FAILED - connect: Device or resource busy (16)

stepen avatar Feb 19 '17 09:02 stepen

Sorry, I cannot reproduce this issue with the only BLE device I have here. :-(

oliviermartin avatar Feb 20 '17 19:02 oliviermartin

The time it takes to connect does seem to be unbearably slow, compared to the regular gatttool

ghost avatar Feb 28 '17 15:02 ghost

I cannot duplicate the issue with my Nordic nRF52 board.

default gatttool

$ time gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m1.170s
user	0m0.000s
sys	0m0.000s
$ time gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m0.095s
user	0m0.004s
sys	0m0.000s
$ time gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m0.111s
user	0m0.000s
sys	0m0.000s
$ time gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

Gattlib gatttool

real	0m0.109s
user	0m0.004s
sys	0m0.000s
$ time ./examples/gatttool/gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m0.530s
user	0m0.004s
sys	0m0.000s
$ time ./examples/gatttool/gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m0.138s
user	0m0.004s
sys	0m0.000s
$ time ./examples/gatttool/gatttool -t random -b DA:94:40:95:E0:87 --char-read -a 0x000e
Characteristic value/descriptor: 03 

real	0m0.075s
user	0m0.000s
sys	0m0.000s

Gattlib read_write

$ time ./examples/read_write/read_write DA:94:40:95:E0:87 read 0x2a38
Read UUID completed: 03 

real	0m0.994s
user	0m0.992s
sys	0m0.000s
$ time ./examples/read_write/read_write DA:94:40:95:E0:87 read 0x2a38
Read UUID completed: 03 

real	0m0.120s
user	0m0.116s
sys	0m0.000s
$ time ./examples/read_write/read_write DA:94:40:95:E0:87 read 0x2a38
Read UUID completed: 03 

real	0m0.109s
user	0m0.108s
sys	0m0.004s
$ time ./examples/read_write/read_write DA:94:40:95:E0:87 read 0x2a38
Read UUID completed: 03 

real	0m0.128s
user	0m0.124s
sys	0m0.000s

oliviermartin avatar Mar 03 '17 16:03 oliviermartin

I am doing it on the Raspberry Pi 3, but I still get some very slow connection.

ghost avatar Mar 23 '17 10:03 ghost

I am having similar problems, and one thing I noticed while trying to debug the problem is that after a gattlib_disconnect the device is disconnected (it starts advertizing again), but bluez thinks it is still connected ("hcitool con" shows the device as still connected)

mweal-ed avatar Jul 12 '17 15:07 mweal-ed

Playing around some more, it looks like this problem has more to do with gattlib/bluez not properly disconnecting so when an attempt is made to re-connect, there is one of a couple (few?) different connection problems that can happen

mweal-ed avatar Jul 14 '17 20:07 mweal-ed

The code posted by @oliviermartin would not compile for me... but I noticed the main difference as why it works. It does not have to do with the async method or not (which the async is really nice to have). It has to do with the BDADDR_LE_RANDOM flag. The issue is that from my blueZ version 4.101 I can only connect to devices with the -t random parameter. I hope this solves the problems for everyone having the same issue! I changed the flag/parameter on the discover example and it work great. The ble_scan needs a bit more modifications for it to work right, but I have not need for it currently since I know the device address I want to connect to.

connection = gattlib_connect_async(NULL, argv[1], BDADDR_LE_RANDOM, BT_SEC_LOW, 0, 0, connect_cb);

Here is the main method on the updated read_write.c

` uint8_t buffer[100]; int i, ret; size_t len; gatt_connection_t* connection;

if ((argc != 4) && (argc != 5)) {
	usage(argv);
	return 1;
}

if (strcmp(argv[2], "read") == 0) {
	g_operation = READ;
} else if ((strcmp(argv[2], "write") == 0) && (argc == 5)) {
	g_operation = WRITE;

	if ((strlen(argv[4]) >= 2) && (argv[4][0] == '0') && (argv[4][0] == 'x')) {
		value_data = strtol(argv[4], NULL, 0);
	} else {
		value_data = strtol(argv[4], NULL, 16);
	}
	printf("Value to write: 0x%lx\n", value_data);
} else {
	usage(argv);
	return 1;
}

if (gattlib_string_to_uuid(argv[3], strlen(argv[3]) + 1, &g_uuid) < 0) {
	usage(argv);
	return 1;
}

connection = gattlib_connect(NULL, argv[1], BDADDR_LE_RANDOM, BT_SEC_LOW, 0, 0);
if (connection == NULL) {
	fprintf(stderr, "Fail to connect to the bluetooth device.\n");
	return 1;
}

if (g_operation == READ) {
	len = sizeof(buffer);
	ret = gattlib_read_char_by_uuid(connection, &g_uuid, buffer, &len);
	assert(ret == 0);

	printf("Read UUID completed: ");
	for (i = 0; i < len; i++)
		printf("%02x ", buffer[i]);
	printf("\n");
} else {
	ret = gattlib_write_char_by_uuid(connection, &g_uuid, buffer, sizeof(buffer));
	assert(ret == 0);
}

gattlib_disconnect(connection);
return 0;

`

an01f01 avatar Oct 06 '17 17:10 an01f01