Bug report – BLE – cant reconnect to a bonded device

Tip / Sign in to post questions, reply, level up, and achieve exciting badges. Know more

cross mob
lock attach
Attachments are accessible only for community members.
StN__1917156
Level 4
Level 4
25 replies posted 10 replies posted 5 replies posted

Running hello_sensor example on CYW20719 (CYBT_413034_EVAL)

On the other side Android 5.0 with CySmart and nRfConnect

Also attached logs from Tera Term

Description of the bug: Once BLE device is bonded and future attempts to reconnect fail until the bonding/ pairing info is deleted at the Android client.

Primary suspect: Cypress’s BLE stack / code. Could be a problem and from Android, but I tried with CC2540 keyfob and connects/disconnect many times without problem to the same clients (CySmart and nRfConnect) after bonded.

The log from CySmart is quite scanty:

[01-Jun-2019|14:35:17] , [Hello1|20:71:9B:19:3E:41] Connection request sent

[01-Jun-2019|14:35:18] , [Hello1|20:71:9B:19:3E:41] Connection established

[01-Jun-2019|14:35:18] , [Hello1|20:71:9B:19:3E:41] Disconnected

[01-Jun-2019|14:38:35] , [Hello1|20:71:9B:19:3E:41] Connection request sent

[01-Jun-2019|14:38:36] , [Hello1|20:71:9B:19:3E:41] Connection established

[01-Jun-2019|14:38:37] , [Hello1|20:71:9B:19:3E:41] Service discovery request sent

[01-Jun-2019|14:38:51] , [Hello1|20:71:9B:19:3E:41] Service discovery status - Failed with error code : 129

[01-Jun-2019|14:38:51] , [Hello1|20:71:9B:19:3E:41] Disconnected

[01-Jun-2019|14:39:20] , [Hello1|20:71:9B:19:3E:41] Connection request sent

[01-Jun-2019|14:39:22] , [Hello1|20:71:9B:19:3E:41] Connection established

[01-Jun-2019|14:39:22] , [Hello1|20:71:9B:19:3E:41] Disconnected

[01-Jun-2019|14:39:58] , [Hello1|20:71:9B:19:3E:41] Unable to pair. Check whether the device is advertising and supports pairing.

While when device is not paired/bonded or the pairing information is just cleared:

[01-Jun-2019|14:33:00] , [Hello1|20:71:9B:19:3E:41] Connection request sent

[01-Jun-2019|14:33:00] , [Hello1|20:71:9B:19:3E:41] Connection established

[01-Jun-2019|14:33:01] , [Hello1|20:71:9B:19:3E:41] Service discovery request sent

[01-Jun-2019|14:33:02] , [Hello1|20:71:9B:19:3E:41] Service discovery status – Success

Attached are and the logs from nRf Connect where there are quite more details:

V             13:16:41.081       Connecting to 20:71:9B:19:3E:41...

D             13:16:41.081       gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE) (hidden)

D             13:16:41.975       [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I               13:16:41.975       [Server] Device with address 20:71:9B:19:3E:41 connected

D             13:16:42.009       [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I               13:16:42.009       Connected to 20:71:9B:19:3E:41

D             13:16:42.013       wait(1600ms)

D             13:16:42.031       [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED

D             13:16:42.215       [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)

I               13:16:42.215       [Server] Device disconnected

D             13:16:42.215       [Callback] Connection state changed with status: 61 and new state: DISCONNECTED (0)

E              13:16:42.240       Error 61 (0x3d): UNKNOWN (61)

I               13:16:42.240       Disconnected

D             13:16:42.272       [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

vs. normal connection to not bonded/paired device:

V             13:34:31.891       Connecting to 20:71:9B:19:3E:41...

D             13:34:31.891       gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE) (hidden)

D             13:34:32.309       [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I               13:34:32.309       [Server] Device with address 20:71:9B:19:3E:41 connected

D             13:34:32.318       [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I               13:34:32.318       Connected to 20:71:9B:19:3E:41

V             13:34:32.353       Discovering services...

D             13:34:32.353       gatt.discoverServices()

D             13:34:32.365       [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED

D             13:34:34.313       [Callback] Services discovered with status: 0

I               13:34:34.313       Services discovered

V             13:34:34.345       Generic Attribute (0x1801)

0 Likes
14 Replies
Owen_Zhang123
Moderator
Moderator
Moderator
5 questions asked 500 solutions authored 250 sign-ins

Which SDK version are you using?

Do you test with the latest Cysmart app?

0 Likes

WICED-SDK Version: Wiced_006.002.001.0002

My guess is the CySmart is the latest version as I installed it from Google PlayStore 2 days ago.

At 'About' screen says CySmart 1.1.1.68

Thanks

0 Likes

Could you try to check the item "Clear cache on disconnect" in the APP. I am not sure why this happens. Per my test, it can connect successfully when I check it.

pastedImage_0.png

0 Likes
lock attach
Attachments are accessible only for community members.

Hi OwenZ_26,

Yes the ‘Clear cache on disconnect’ is (and was) marked.

Are you sure you’ve tested with pairing/bonding? Because I also, if only  just connect and read or write some attributes, will have next reconnections working Ok.

But as soon as switch on notifications in the ‘hello_sensor’ example, this automatically performs pairing and bonding, and any next attempt to reconnect to already paired/bonded ‘Hello1’ fails!

And you can see if the ‘Hello1’ is paired when you return to the BLE devices list in CySmart:  The button on the right of ‘Hello1’ is “Paired”-pic8  vs. “Not Paired” – pic2

Or you can go to AndroidSettings>Bluetooth and if the ‘Hello1’ is paired it is in the section “Paired devices”- pic9, but if it still not paired, but available for connection (advertising) – it is down in the bottom section “Available devices” – pic1

Test 4-6-19:

CySmart stopped making logs (or I forgot how I switched logging On last time), so attached is only the log from Tera Term with my comments (***) what manual operations was performed:

** Starting with not paired Hello1 (hello_sensor) pic1,pic2:

pic1.png  pic2.png

*** Connect to Hello1

*** Read and write couple attributes pic3,pic4:

pic3.pngpic4.png

*** Back>Back to List BLE devices: same as pic1,pic2

***Reconnect to Hello1 (still not bonded)

*** Click on 'Notify' for characteristic  xxxx626 ->pic6 -> paring/bonding executed automatically

pic6:

pic6.png

** Read some characteristics and pressed button on CBYT_413034_EVAL.... to get notification -pic7:

pic7.png

***Exit with Back>Back to BLE list

*** Reconnect to Hello1 (already bonded) pic8,pic9....

pic8.png pic9.png

and fails after: pic10,pic11:

pic10.pngpic11.png

*** Reconnect after cleared Pairing for Hello1 from CySmart same as pic2 > reconnects Ok

(pairing can be cleared and from AndroidSettings>Bluetooth>Hello1>Unpair)

*** Exit > Finish the test

0 Likes
lock attach
Attachments are accessible only for community members.

I tested as you said:

1. connect the device with cysmart

2. enable notify and press button on the kit to receive notify

3. back to BLE device list

4. try to reconnect

I have tested it for several times and I can reconnect to the device successfully.

It seems to be the notify's problem from your description. Then I compare the log from cysmart with yours. I found when I back to the initial connection page, the cysmart will say all the notify and indicate are disabled. I can also find the request in the log of cysmart. But when I see your logs, I can't find the notify disable request.

Could you try to test the problem with another phone?

pastedImage_0.png

pastedImage_1.png

0 Likes

I am getting the same toast "All indications and notifications disabled" on the screen like you.

Cant see the log anymore in CySmart - will have to reinstall it tomorrow.

I doubt the problem is "Notify" - I can connect to the CYBT413034 and from nRfConnect where  there is separate 'Bond' command from Options Menu, so can perform the bonding manually without need to go to Notifications in order to trigger Pairing/Bonding.

And I tried with one Texas Instruments  keyfob  with CC2540 and Simple BLE Peripheral application installed on it and can bond manually(with nRfConnect) or through 'Notify' with CySmart or nRfConnect , but dont have problem to reconnect after is bonded - this problem happens only with CYBT413043 and is consistent

What is the minimal version Android required for CySmart to run?

Let me try first to make CySmart log work and after will try to compare yours and my log for the same operations to see where the differ

0 Likes
lock attach
Attachments are accessible only for community members.

So I was able to recover the CySmart log file that corresponds to the above detail test explanation, as well added corresponding  timestamps in the trace/debug file from the CYW20719 and they are both attached to this post.

Next: compared side by side with your log you've posted yesterday: I dont see any difference with notification stopping. Cant see and any significant differences  other than when trying to reconnect to already bonded device.

Could you, please, elaborate more on the following error codes as I assume you have access to source of Cypres's BT stack and source for the CySmart:

[04-Jun-2019|16:13:16] , [Hello1|20:71:9B:19:3E:41] Service discovery status - Failed with error code : 129

Encryption Status Event: bd ( e4 b0 cf 38 ba 96  ) res 8109

encryp change bd ( e4 b0 cf 38 ba 96  ) res: 8109

connection_down e4 b0 cf 38 ba 96  conn_id:1 reason:61

Thanks

0 Likes

Tried with 3 different devices as client - similar errors happened, worst case is ( e4 b0 cf 38 ba 96  ) where only once was able to pass Ok recconnection

hello_sensor_management_cback: c

Encryption Status Event: bd ( ef 25 b1 1e c4 f9  ) res 0encryp change bd ( ef 25 b1 1e c4 f9  ) res: 0 

connection_down ef 25 b1 1e c4 f9  conn_id:1 reason:8

hello_sensor_management_cback: c

Encryption Status Event: bd ( ef 25 b1 1e c4 f9  ) res 8109encryp change bd ( ef 25 b1 1e c4 f9  ) res: 8109

connection_down ef 25 b1 1e c4 f9  conn_id:1 reason:61

hello_sensor_management_cback: c

Encryption Status Event: bd ( e4 b0 cf 38 ba 96  ) res 8109encryp change bd ( e4 b0 cf 38 ba 96  ) res: 8109

connection_down e4 b0 cf 38 ba 96  conn_id:1 reason:61

hello_sensor_management_cback: c

Encryption Status Event: bd ( 58 b1 0f cf 0e 1d  ) res 8109encryp change bd ( 58 b1 0f cf 0e 1d  ) res: 8109

connection_down 58 b1 0f cf 0e 1d  conn_id:1 reason:61

So my questions are:

1. Where can read Encryption Status event result codes meaning and  connection events reason codes meanings?

2. What possibilities have to adjust timeout values in L2CAP and whatever other timeouts are available between SM and LL layers in the BLE stack?

Thanks

P.S. For ( ef 25 b1 1e c4 f9  ) and ( 58 b1 0f cf 0e 1d  ) I already figured what is the reason for 8109, but for the other cant find yet work around

0 Likes

That's quite strange. I also tested with several device with Android 6.0 and 4.4.4. All of them works correctly.

You can try to route the trace logs to  WICED_ROUTE_DEBUG_TO_WICED_UART for more details.  Please refer to chapter 4.4.3 in CYW207x9WCDEVAL-BT-Quick-Start-Guide.pdf under the doc folder about how to route log to BTSpy.

Tried all the 3 documents that describe debugging procedure with BTSpy (all contradicting ☹ each other in some way) and still cant score to display traces in BTSpy ☹

CYW9207x9WCDEVAL Quick Start Guide 4.4.3

WBT101-05-Debugging.pdf 5.2.4

CYW920719Q40EVB-01 Evaluation Board User Guide Doc. No.: 002-22816 Rev. *A  2.6.7.3

Tried output traces on standard terminal: can see traces, but don’t see any additional information from what was displayed on the PUART except that some of the text are with “monkeys”

wiced_set_debug_uart (WICED_ROUTE_DEBUG_TO_WICED_UART)

C_FLAGS += -DENABLE_HCI_TRACE -DWICED_BT_TRACE_ENABLE

Trace2HCI_2.png

Also found  one more bug: when

wiced_set_debug_uart (WICED_ROUTE_DEBUG_TO_HCI_UART)   (or no wiced_set_debug_uart defined at all)

C_FLAGS += -DWICED_BT_TRACE_ENABLE

The trace on HCI com port (in my case COM4) start normal (like what I can see on the PUART) and at certain point switch on automatically itself to same “monkey” encoding what I see when debug with settings for BTSpy ☹

Trace2HCI_1.png

0 Likes

So finally got BTSpy running The problems are:

1. Dont put too much credit what you read in the Cypress documentations "In the ClientControl utility, set the baud rate to the baud rate used by the application (3000000 for Hello Sensor..."  - double and triple check wherever possible - the actual baudrate for Hello Sensor app with CYW20719 on CYBT_413034 is 115200

2. ClientControl doesnt start properly every time - need many attempts and waiting with connect/disconnect port until you finally  get sacral message "Client Control app established communication with Bluetooth device." - then only you could get trace on BTSpy. At least at the end after couple successful connections started connecting almost right away - probably cached some connection parameters in the Windows registry

0 Likes
lock attach
Attachments are accessible only for community members.

Ok, Finaly got some trace that have some more information: 11:14:26.127

Connection Terminated Due to MIC Failure (0x3d)

This is after pairing/bonding -> disconnect -> try to reconnect already bonded CYW21709.

If you dont have right away magic solution to solve the problem, could you at least elaborate what is the source of this Message Integrity Check: CYW20719 | Android | CySmart and who initiates disconnection?

Thanks

11:14:26.105 1 hello_sensor_conn_up e4 b0 cf 38 ba 96  id:1

:

11:14:26.109 1 hello_sensor_management_cback: 17

11:14:26.114 1 Advertisement State Change: 0

11:14:26.114 1 ADV stop

11:14:26.116 1 Stopping Advertisements0

11:14:26.118 1 NVRAM write 9

11:14:26.122 1 hello_sensor_management_cback: 17

11:14:26.124 1 Advertisement State Change: 0

11:14:26.127 1 ADV stop

11:14:26.127 RCVD [1] Event from HCI.  Name: HCI_Encryption_Change   (Hex Code: 0x08  Param Len: 4)

11:14:26.127                                   Status : Connection Terminated Due to MIC Failure (0x3d)

11:14:26.127                        Connection Handle : 64 (0x0040)

11:14:26.127                        Encryption Enable : 0 (0x00)

11:14:26.131 1 hello_sensor_management_cback: c

11:14:26.135 1 Encryption Status Event: bd ( e4 b0 cf 38 ba 96  ) res 8109

11:14:26.142 1 encryp change bd ( e4 b0 cf 38 ba 96  ) res: 8109

11:14:26.142 RCVD [1] Event from HCI.  Name: HCI_Disconnection_Complete   (Hex Code: 0x05  Param Len: 4)

11:14:26.142                                   Status : Success (0x00)

11:14:26.142                        Connection Handle : 64 (0x0040)

11:14:26.142                                   Reason : 61 (0x3d)

11:14:26.142                                            Connection Terminated Due to MIC Failure

11:14:26.148 1 connection_down e4 b0 cf 38 ba 96  conn_id:1 reason:61

0 Likes

I tested this problem on Huawei Honor, Hisense and Red Mi, but I can't reproduce your problem. I think it is related with the phone.

0 Likes

Most probably is not the phone/tablet problem - maybe the version of the Android (in this case 5.0.1) contribute to the problem, but I tried other BLE devices from TI and they reconnect  bonded without any problem to all Android and Windows Devices I tried. I tried with different devices with different versions of Android to source route cause, but the problem is that every version of Android connects to CYW with different connection parameters (Supevision timeout and Clock Accuracy) as well the sequence of the conversation at the point where this encryption error happens is different - for example when connecting to Android 4.4 there are few extra send/receives  before HCI_Encryption_Change and unless the last device bonded to CYW was not the same, the returned status is ) (success). 

Here is the sample of the CYW log when connecting to Android 4.4 device (in Android 5.* the lines from 13:16:49.142 to 13:16:49.312 - the ones I tabbed right - dont appear in the log)!

13:16:49.118 1 hello_sensor_conn_up 58 b1 0f cf 0e 1d  id:1

:

13:16:49.123 1 hello_sensor_management_cback: 17

13:16:49.125 1 Advertisement State Change: 0

13:16:49.127 1 ADV stop

13:16:49.129 1 Stopping Advertisements0

13:16:49.132 1 NVRAM write 9

13:16:49.136 1 hello_sensor_management_cback: 17

13:16:49.138 1 Advertisement State Change: 0

13:16:49.140 1 ADV stop

13:16:49.142 ATT SEND Command. Name: Read By Group Type Response (0x11) len: 14

13:16:49.143                    Handle Value Pair Len :6

13:16:49.143                              Group Range : [0x0001 ~ 0x0001]

13:16:49.143                                    Value : 01 18

13:16:49.143                              Group Range : [0x0014 ~ 0x0018]

13:16:49.143                                    Value : 00 18

13:16:49.310 RCVD [1] Event from HCI.  Name: HCI_BLE_Event  (Hex Code: 0x3e  Param Len: 13)

13:16:49.310                HCI_BLE_LTK_Request_Event : 5 (0x05)

13:16:49.310                        Connection Handle : 64 (0x0040)

13:16:49.310                            Random Number : b1 fa 1f 6a da 07 8a c6

13:16:49.310                                    EDIV : 31907 (0x7ca3)

13:16:49.312 SENT [1] Command to HCI.  Name: HCI_LE_Long_Term_Key_Request_Reply  (Hex Code: 0x201a  Param Len: 18)

13:16:49.312                        Connection Handle : 64 (0x0040)

13:16:49.312                                      LTK : de 89 d0 07 1f d1 aa d9 67 c2 4a 45 94 8f 66 6b

13:16:49.312 RCVD [1] Event from HCI.  Name: HCI_Command_Complete  (Hex Code: 0x0e  Param Len: 6)

13:16:49.312                      Num HCI Cmd Packets : 1 (0x01)

13:16:49.312                                Cmd Code : 0x201a  (HCI_LE_Long_Term_Key_Request_Reply)

13:16:49.312                                  Status : Success (0x00)

13:16:49.312                                  Handle : 64 (0x0040)

13:16:49.552 RCVD [1] Event from HCI.  Name: HCI_Encryption_Change  (Hex Code: 0x08  Param Len: 4)

13:16:49.552                                  Status : Success (0x00)

Here is the same passage of the sequence from CYW log when connecting from Android 5:

23:45:07.790 1 hello_sensor_conn_up e4 b0 cf 38 ba 96  id:1

:

23:45:07.792 1 hello_sensor_management_cback: 17

23:45:07.796 1 Advertisement State Change: 0

23:45:07.796 1 ADV stop

23:45:07.799 1 Stopping Advertisements0

23:45:07.801 1 NVRAM write 9

23:45:07.805 1 hello_sensor_management_cback: 17

23:45:07.807 1 Advertisement State Change: 0

23:45:07.810 1 ADV stop

23:45:07.810 RCVD [1] Event from HCI.  Name: HCI_Encryption_Change   (Hex Code: 0x08  Param Len: 4)

23:45:07.810                                   Status : Connection Terminated Due to MIC Failure (0x3d)

0 Likes