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)
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 220.127.116.11
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.
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
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:
*** Connect to Hello1
*** Read and write couple attributes pic3,pic4:
*** 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
** Read some characteristics and pressed button on CBYT_413034_EVAL.... to get notification -pic7:
***Exit with Back>Back to BLE list
*** Reconnect to Hello1 (already bonded) pic8,pic9....
and fails after: pic10,pic11:
*** 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
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?
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
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
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
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
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
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
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?
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
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
CYW920719Q40EVB-01 Evaluation Board User Guide Doc. No.: 002-22816 Rev. *A 18.104.22.168
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”
C_FLAGS += -DENABLE_HCI_TRACE -DWICED_BT_TRACE_ENABLE
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 ☹
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
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?
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  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  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
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.
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  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  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  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  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  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)