Unable to connect to our product from one particular phone

[Trygve Laugstøl]

Hi

After doing a rebuild of a previously working project, my personal phone and a test phone is unable to connect to our product.

The device is discovered by the phone without a problem, but always times out when trying to connect. This happens from our app and from nRF Connect:

nRF Connect, 2020-02-08
Nordic_HRM (FD:B1:75:DE:F5:1A)
D    22:33:32.630    gatt.close()
D    22:33:32.632    wait(200)
V    22:33:32.834    Connecting to FD:B1:75:DE:F5:1A...
D    22:33:32.834    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D    22:34:02.844    [Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E    22:34:02.844    Error 133 (0x85): GATT ERROR
I    22:34:02.844    Disconnected

I have used the nrf sniffer with Wireshark, and I can't see a single packet from my phone when it is trying to connect to the device. The phone can connect to the previous version of our firmware on our device and on the PCA10040 kits. It work from other phones.

If I use the unmodified ble_app_hrs examples on a PCA10040, I get the same behaviour. I can't connect from my phone, but it work from other phones.

I honestly have no idea what can be wrong, and I have spent a lot of time to try to understand this.

Does anybody have a clue? It is hard to say that there is something wrong with the Nordic stuff since it works on other phones, at the same time it is strange that my phone should be picky about this particular build since old builds and other devices with just fine with it. Is there anything I can reset to shake this out?

Environment

My phone is a Google Pixel (G-2PW4100) running Android 10.

The test phone is an 3 year old Samsung phone, running something older than Android 10.

I'm building the firmware with SES 4.40, I'm not quite sure which version we used to build the original firmware with.

The original firmware is built with SDK 15.0.0 and we used the same for our DFU build.

[Trygve Laugstøl]

I just opened nRF connect again, just to see if it works now, and it connected! Hit reset on the device, tried to connect again and it was back to the old behavior:

nRF Connect, 2020-02-10
Nordic_HRM (FD:B1:75:DE:F5:1A)
V	22:02:49.554	Connecting to FD:B1:75:DE:F5:1A...
D	22:02:49.554	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:02:49.930	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	22:02:49.963	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:02:49.963	Connected to FD:B1:75:DE:F5:1A
V	22:02:49.973	Requesting new MTU...
D	22:02:49.973	gatt.requestMtu(517)
I	22:02:50.369	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	22:02:50.643	MTU changed to: 247
V	22:02:50.655	Discovering services...
D	22:02:50.655	gatt.discoverServices()
D	22:02:50.666	[Callback] Services discovered with status: 0
I	22:02:50.666	Services discovered
V	22:02:50.689	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
D	22:02:50.690	gatt.setCharacteristicNotification(00002a37-0000-1000-8000-00805f9b34fb, true)
D	22:02:50.693	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	22:02:50.711	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	22:02:55.819	Connection parameters updated (interval: 645.0ms, latency: 0, timeout: 4000ms)
V	22:03:06.428	Disconnecting...
D	22:03:06.428	gatt.disconnect()
D	22:03:06.449	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	22:03:06.449	Disconnected
D	22:03:07.702	gatt.close()
D	22:03:07.703	wait(200)
V	22:03:07.905	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:07.905	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:07.932	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:07.932	Connected to FD:B1:75:DE:F5:1A
V	22:03:07.934	Requesting new MTU...
D	22:03:07.934	gatt.requestMtu(517)
W	22:03:10.730	Connection parameters update failed with status 22 (interval: 645.0ms, latency: 0, timeout: 4000ms)
E	22:03:10.730	Error 22 (0x16): UNKNOWN (22)
D	22:03:10.807	[Callback] Connection state changed with status: 22 and new state: DISCONNECTED (0)
D	22:03:10.807	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
E	22:03:10.831	Error 22 (0x16): GATT CONN TERMINATE LOCAL HOST
I	22:03:10.831	Disconnected
D	22:03:11.793	gatt.close()
D	22:03:11.796	wait(200)
V	22:03:11.998	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:11.999	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:12.692	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:12.692	Connected to FD:B1:75:DE:F5:1A
V	22:03:12.696	Requesting new MTU...
D	22:03:12.696	gatt.requestMtu(517)
D	22:03:12.716	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	22:03:13.136	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	22:03:13.416	MTU changed to: 247
V	22:03:13.450	Discovering services...
D	22:03:13.450	gatt.discoverServices()
D	22:03:13.502	[Callback] Services discovered with status: 0
I	22:03:13.502	Services discovered
V	22:03:13.539	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
D	22:03:13.539	gatt.setCharacteristicNotification(00002a37-0000-1000-8000-00805f9b34fb, true)
D	22:03:13.543	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	22:03:13.583	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	22:03:14.794	Disconnecting...
D	22:03:14.794	gatt.disconnect()
D	22:03:14.809	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	22:03:14.809	Disconnected
D	22:03:15.347	gatt.close()
D	22:03:15.350	wait(200)
V	22:03:15.553	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:15.553	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:15.577	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:15.577	Connected to FD:B1:75:DE:F5:1A
V	22:03:15.578	Requesting new MTU...
D	22:03:15.578	gatt.requestMtu(517)
I	22:03:15.927	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
E	22:03:16.181	Error 4 (0x4): GATT INVALID PDU
V	22:03:16.217	Discovering services...
D	22:03:16.217	gatt.discoverServices()
D	22:03:16.230	[Callback] Services discovered with status: 0
I	22:03:16.230	Services discovered
V	22:03:16.244	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
D	22:03:16.244	gatt.setCharacteristicNotification(00002a37-0000-1000-8000-00805f9b34fb, true)
D	22:03:16.247	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	22:03:16.268	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	22:03:17.527	Disconnecting...
D	22:03:17.527	gatt.disconnect()
D	22:03:17.551	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	22:03:17.551	Disconnected
D	22:03:18.366	gatt.close()
D	22:03:18.367	wait(200)
V	22:03:18.572	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:18.572	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:18.600	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I	22:03:18.618	Disconnected
D	22:03:18.767	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	22:03:18.767	gatt.close()
D	22:03:18.769	wait(200)
V	22:03:18.970	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:18.970	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:18.993	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:18.993	Connected to FD:B1:75:DE:F5:1A
V	22:03:18.995	Requesting new MTU...
D	22:03:18.995	gatt.requestMtu(517)
E	22:03:19.167	Error 10 (0xa): GATT NOT FOUND
V	22:03:19.196	Discovering services...
D	22:03:19.196	gatt.discoverServices()
D	22:03:19.210	[Callback] Services discovered with status: 0
I	22:03:19.210	Services discovered
V	22:03:19.210	No services found 
I	22:03:19.228	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	22:03:19.370	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	22:03:24.153	Disconnecting...
D	22:03:24.153	gatt.disconnect()
D	22:03:24.183	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	22:03:24.183	Disconnected
D	22:03:24.957	gatt.close()
D	22:03:24.958	wait(200)
V	22:03:25.160	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:25.161	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:25.182	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:25.182	Connected to FD:B1:75:DE:F5:1A
V	22:03:25.182	Requesting new MTU...
D	22:03:25.182	gatt.requestMtu(517)
W	22:03:25.550	Connection parameters update failed with status 22 (interval: 645.0ms, latency: 0, timeout: 4000ms)
E	22:03:25.550	Error 22 (0x16): UNKNOWN (22)
D	22:03:25.583	[Callback] Connection state changed with status: 22 and new state: DISCONNECTED (0)
E	22:03:25.583	Error 22 (0x16): GATT CONN TERMINATE LOCAL HOST
I	22:03:25.583	Disconnected
D	22:03:25.583	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	22:03:30.657	gatt.close()
D	22:03:30.660	wait(200)
V	22:03:30.862	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:30.863	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:31.367	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:31.367	Connected to FD:B1:75:DE:F5:1A
V	22:03:31.369	Requesting new MTU...
D	22:03:31.369	gatt.requestMtu(517)
D	22:03:31.394	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	22:03:31.812	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	22:03:32.089	MTU changed to: 247
V	22:03:32.104	Discovering services...
D	22:03:32.104	gatt.discoverServices()
D	22:03:32.119	[Callback] Services discovered with status: 0
I	22:03:32.119	Services discovered
V	22:03:32.136	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
D	22:03:32.136	gatt.setCharacteristicNotification(00002a37-0000-1000-8000-00805f9b34fb, true)
D	22:03:32.138	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	22:03:32.154	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	22:03:34.981	Disconnecting...
D	22:03:34.981	gatt.disconnect()
D	22:03:35.001	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	22:03:35.001	Disconnected
D	22:03:36.014	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	22:03:36.356	gatt.close()
D	22:03:36.358	wait(200)
V	22:03:36.560	Connecting to FD:B1:75:DE:F5:1A...
D	22:03:36.560	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:03:36.991	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:03:36.991	Connected to FD:B1:75:DE:F5:1A
D	22:03:36.994	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V	22:03:37.032	Requesting new MTU...
D	22:03:37.032	gatt.requestMtu(517)
I	22:03:37.436	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	22:03:37.713	MTU changed to: 247
V	22:03:37.730	Discovering services...
D	22:03:37.730	gatt.discoverServices()
D	22:03:37.746	[Callback] Services discovered with status: 0
I	22:03:37.746	Services discovered
V	22:03:37.762	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
D	22:03:37.762	gatt.setCharacteristicNotification(00002a37-0000-1000-8000-00805f9b34fb, true)
D	22:03:37.764	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	22:03:37.777	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	22:03:42.889	Connection parameters updated (interval: 645.0ms, latency: 0, timeout: 4000ms)
D	22:03:50.719	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	22:03:50.720	Error 8 (0x8): GATT CONN TIMEOUT
I	22:03:50.720	Disconnected
D	22:03:50.833	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	22:04:00.095	gatt.close()
D	22:04:00.097	wait(200)
V	22:04:00.300	Connecting to FD:B1:75:DE:F5:1A...
D	22:04:00.300	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:04:40.713	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	22:04:40.713	Connected to FD:B1:75:DE:F5:1A
V	22:04:40.714	Requesting new MTU...
D	22:04:40.715	gatt.requestMtu(517)
D	22:04:40.797	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	22:04:40.797	[Callback] Connection state changed with status: 34 and new state: DISCONNECTED (0)
E	22:04:40.797	Error 34 (0x22): GATT CONN LMP TIMEOUT
I	22:04:40.797	Disconnected
D	22:04:40.839	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	22:07:55.619	gatt.close()
D	22:07:55.620	wait(200)
V	22:07:55.823	Connecting to FD:B1:75:DE:F5:1A...
D	22:07:55.824	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	22:08:25.832	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	22:08:25.832	Error 133 (0x85): GATT ERROR
I	22:08:25.832	Disconnected

[Simonr]

Hi Trygve

Where exactly do you hit the reset where the device is back to its old behavior here. It seems like there are multiple resets and disconnects with various disconnect reasons. Error 22, for example, being the host terminating the connection itself, which is your phone disconnecting from the device manually. I assume only the last reset and disconnect with error 133 is what you mean.

Unfortunately, error 133 is just a "general BLE error" which makes it hard to figure out what exactly is the issue. It is usually due to the Android stack receiving something unexpectedly though. I know there have been quite a bit of problems with Android 10 on the Google Pixel phones, so that might be what's causing these sporadic disconnects as well. 

I know you said you didn't see anything useful in the sniffer trace you made, but could you upload it so we could have a look as well?

Best regards,

Simon

[Trygve Laugstøl]

Hi Simon.

Sorry, I should have noted down exactly what I did but it was just a last test when looking at your latest reply.

I think some of the errors are because the phone is confused after I pressed reset on the device, before the connection has timed out on the phone's side.

A couple of things that stand out: 22:03:19.167    Error 10 (0xa): GATT NOT FOUND and "gatt.requestMtu(517)". Isn't that MTU way to big for the device? Is that something that can trigger anything? It is supposed to negotiate the size, but you never know.

I will do a new sniffer trace and upload at the end of this week, I'm out of office for a couple of days.

--
Trygve

[Simonr]

Hi Trygve

I'm sorry, but without seeing the more detailed sniffer side of things it's hard to say why the GATT NOT FOUND error occurs. The GATT request is nothing out of the ordinary, as 517 the default value Android phones request when updating MTU if I'm not mistaken. As this is just a request, the nRF52832 will reply by updating the MTU to as much as it can handle, being 247, which is reflected in the MTU changed to: 247 messages.

Best regards,

Simon