• State Not Answered
  • Replies 3 replies
  • Subscribers 74 subscribers
  • Views 631 views
  • Users 0 members are here
Attachments (4) Download All
Nordic Case Info
  • Case ID: 318328
Options

Slave BLE nRF52-based device often has long response delays to master

nategreco

This is (hopefully) a more concise question than what was originally asked here.  When looking at nRF Sniffer captures while investigating that ticket, I discovered this problem which is likely causing a variety of issues.

My nRF52-based device frequently fails to respond to the master in a timely manner.  The issue is particularly bad when initially establishing a connection.  Here's an example:

663	17.716720	64:b8:bc:c8:c4:f3	d8:80:e7:6f:45:df	LE LL	60	CONNECT_IND
664	17.741230	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	35	Control Opcode: LL_FEATURE_REQ
665	17.741531	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	26	Empty PDU
666	17.741761	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	26	Empty PDU
...Device fails to reply...
667	21.642401	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	26	Empty PDU
668	21.642630	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	35	Control Opcode: LL_FEATURE_RSP <-- 3.9s to reply!
...Device fails to reply (Frame 667)...
669	22.373635	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	26	Empty PDU
670	22.373865	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	26	Empty PDU
671	22.374096	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	32	Control Opcode: LL_VERSION_IND
...Device fails to reply...
672	22.909875	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	32	Control Opcode: LL_VERSION_IND <--REPEATED
673	22.910152	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	35	Control Opcode: LL_SLAVE_FEATURE_REQ
674	22.910454	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	26	Empty PDU
...Device fails to reply...
675	23.202373	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	26	Empty PDU
676	23.202603	Slave_0x9f4412d0	Master_0x9f4412d0	L2CAP	42	Connection Parameter Update Request
677	23.202962	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	35	Control Opcode: LL_FEATURE_RSP
...Device fails to reply...
678	23.689862	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	35	Control Opcode: LL_FEATURE_RSP <--REPEATED
679	23.690164	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	32	Control Opcode: LL_VERSION_IND
680	23.690441	Master_0x9f4412d0	Slave_0x9f4412d0	ATT	37	Sent Read By Type Request, Server Supported Features, Handles: 0x0001..0xffff
...Device fails to reply...
681	23.933610	Master_0x9f4412d0	Slave_0x9f4412d0	ATT	37	Sent Read By Type Request, Server Supported Features, Handles: 0x0001..0xffff <--REPEATED
682	23.933928	Slave_0x9f4412d0	Master_0x9f4412d0	LE LL	26	Empty PDU
683	23.934158	Master_0x9f4412d0	Slave_0x9f4412d0	LE LL	38	Control Opcode: LL_CONNECTION_UPDATE_IND
...Device fails to reply...Or does that Opcode indicate disconnect?
684	26.915261	d8:80:e7:6f:45:df	Broadcast	LE LL	59	ADV_IND
685	26.915743	71:92:a0:33:a0:34	Broadcast	LE LL	63	ADV_NONCONN_IND

The master indicates a 5000 ms timeout which is frequently violated.  Connection usually fails 1 of every 5 times because of the timing issues. This capture is actually a failure even though the 5 second timeout isn't violated (possibly something app side on the connecting device doesn't tolerate the delays well).  Here's one with a clear 5 seconds before disconnect:

6201	25.566704	64:b8:bc:c8:c4:f3	d8:80:e7:6f:45:df	LE LL	60	CONNECT_IND
6202	25.575073	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	35	Control Opcode: LL_FEATURE_REQ
6203	25.575375	Slave_0x58d1c59c	Master_0x58d1c59c	LE LL	26	Empty PDU
6204	25.575605	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
...Device fails to reply...
6205	29.427505	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
6206	29.427735	Slave_0x58d1c59c	Master_0x58d1c59c	LE LL	35	Control Opcode: LL_FEATURE_RSP <--4.9s to reply!
6207	29.963747	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	32	Control Opcode: LL_VERSION_IND
6208	29.964025	Slave_0x58d1c59c	Master_0x58d1c59c	LE LL	26	Empty PDU
6209	29.964255	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
...Device fails to reply...
6210	31.572468	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
6211	31.572699	Slave_0x58d1c59c	Master_0x58d1c59c	LE LL	32	Control Opcode: LL_VERSION_IND <-- REPEATED
6212	31.572977	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
...Device fails to reply...
6213	32.401202	Master_0x58d1c59c	Slave_0x58d1c59c	LE LL	26	Empty PDU
6214	32.401432	Slave_0x58d1c59c	Master_0x58d1c59c	L2CAP	42	Connection Parameter Update Request
...Device fails to reply and times out after 5 seconds...
6215	37.428454	d8:80:e7:6f:45:df	Broadcast	LE LL	59	ADV_IND


To make sure my app isn't hanging I added a bunch of debug lines to my main loop - As far as I can tell my app itself doesn't hang and that sleep is usually active for about ~250 ms of the 500 ms loop so there should be sufficient resources for the BLE stack to respond.  There are many print lines during the gaps in time my device doesn't respond.

Here is the exact commit used to generate the Wireshark capture and RTT output logs below. 

  • Fullscreen 0216.genuine-failure.txt Download 
    genuine-failure

00> *** Booting Zephyr OS build v3.2.99-ncs2 ***
00> [00:00:00.132,385] <inf> ftms: FTMS initialized
00> [00:00:00.135,284] <inf> app: Starting application, board: ubike_v03
00> [00:00:00.135,314] <inf> app: Software: fix-ftms-connection:bcd7f089767a691cad98652c86321f6be519ad40
00> [00:00:00.135,345] <inf> app: Registering callbacks...
00> [00:00:00.135,345] <inf> app: Configuring GPIO...
00> [00:00:00.135,467] <inf> app: Starting Uart1...
00> [00:00:00.135,467] <inf> app: Checking Uart1 ready...
00> [00:00:00.135,498] <inf> app: Configuring Uart1...
00> [00:00:00.135,528] <inf> app: Initializing bluetooth...
00> [00:00:00.135,559] <err> bt_gatt: Unable to register handle 0x002c
00> [00:00:00.135,681] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
00>                                             d8 0c 2d 2f 36 ae e2 5c  80 26 80 4c 3f 4d 16 53 |..-/6..\ .&.L?M.S
00>                                             50 96 c7 73                ed
00> 
00> [00:00:03.190,460] <wrn> app: Failed to get rs485 semaphore!  Transmitting anyways...
00> [00:00:03.351,409] <inf> app: Starting Display...
00> [00:00:03.367,156] <inf> display: Resetting timer...
00> [00:00:04.132,659] <inf> app: Startup complete!  Entering loop...
00> [00:00:04.132,690] <inf> app: Execution cycle: 0
00> [00:00:04.132,690] <inf> app: Before updateBike()
00> [00:00:04.149,963] <inf> bike: Changing resistance magnitude to: 15
00> [00:00:04.166,595] <inf> app: Before getBikeData()
00> [00:00:04.166,595] <inf> app: Before cscs notify
00> [00:00:04.166,625] <inf> app: Before cps notify
00> [00:00:04.166,625] <inf> app: Before ftms bike data notify
00> [00:00:04.166,656] <inf> app: Before ftms status notify
00> [00:00:04.166,656] <inf> app: Before updateDisplay()
00> [00:00:04.383,697] <inf> app: Before sleep
00> [00:00:04.632,812] <inf> app: After sleep
00> [00:00:04.632,812] <inf> app: Execution cycle: 1
00> [00:00:04.632,843] <inf> app: Before updateBike()
00> [00:00:04.650,665] <inf> app: Before getBikeData()
00> [00:00:04.650,695] <inf> app: Before cscs notify
00> [00:00:04.650,695] <inf> app: Before cps notify
00> [00:00:04.650,695] <inf> app: Before ftms bike data notify
00> [00:00:04.650,726] <inf> app: Before ftms status notify
00> [00:00:04.650,726] <inf> app: Before updateDisplay()
00> [00:00:04.863,098] <inf> app: Before sleep
00> [00:00:05.132,202] <inf> app: After sleep
00> [00:00:05.132,232] <inf> app: Execution cycle: 2
00> [00:00:05.132,232] <inf> app: Before updateBike()
00> [00:00:05.150,177] <inf> app: Before getBikeData()
00> [00:00:05.150,177] <inf> app: Before cscs notify
00> [00:00:05.150,207] <inf> app: Before cps notify
00> [00:00:05.150,207] <inf> app: Before ftms bike data notify
00> [00:00:05.150,238] <inf> app: Before ftms status notify
00> [00:00:05.150,238] <inf> app: Before updateDisplay()
00> [00:00:05.362,762] <inf> app: Before sleep
00> [00:00:05.632,843] <inf> app: After sleep
00> [00:00:05.632,873] <inf> app: Execution cycle: 3
00> [00:00:05.632,873] <inf> app: Before updateBike()
00> [00:00:05.650,482] <inf> app: Before getBikeData()
00> [00:00:05.650,512] <inf> app: Before cscs notify
00> [00:00:05.650,512] <inf> app: Before cps notify
00> [00:00:05.650,543] <inf> app: Before ftms bike data notify
00> [00:00:05.650,543] <inf> app: Before ftms status notify
00> [00:00:05.650,543] <inf> app: Before updateDisplay()
00> [00:00:05.862,823] <inf> app: Before sleep
00> [00:00:06.132,934] <inf> app: After sleep
00> [00:00:06.132,934] <inf> app: Execution cycle: 4
00> [00:00:06.132,965] <inf> app: Before updateBike()
00> [00:00:06.150,360] <inf> app: Before getBikeData()
00> [00:00:06.150,390] <inf> app: Before cscs notify
00> [00:00:06.150,390] <inf> app: Before cps notify
00> [00:00:06.150,421] <inf> app: Before ftms bike data notify
00> [00:00:06.150,421] <inf> app: Before ftms status notify
00> [00:00:06.150,451] <inf> app: Before updateDisplay()
00> [00:00:06.362,121] <inf> app: Before sleep
00> [00:00:06.632,232] <inf> app: After sleep
00> [00:00:06.632,232] <inf> app: Execution cycle: 5
00> [00:00:06.632,232] <inf> app: Before updateBike()
00> [00:00:06.649,810] <inf> app: Before getBikeData()
00> [00:00:06.649,810] <inf> app: Before cscs notify
00> [00:00:06.649,841] <inf> app: Before cps notify
00> [00:00:06.649,841] <inf> app: Before ftms bike data notify
00> [00:00:06.649,871] <inf> app: Before ftms status notify
00> [00:00:06.649,871] <inf> app: Before updateDisplay()
00> [00:00:06.861,724] <inf> app: Before sleep
00> [00:00:07.132,843] <inf> app: After sleep
00> [00:00:07.132,873] <inf> app: Execution cycle: 6
00> [00:00:07.132,873] <inf> app: Before updateBike()
00> [00:00:07.150,543] <inf> app: Before getBikeData()
00> [00:00:07.150,573] <inf> app: Before cscs notify
00> [00:00:07.150,573] <inf> app: Before cps notify
00> [00:00:07.150,573] <inf> app: Before ftms bike data notify
00> [00:00:07.150,604] <inf> app: Before ftms status notify
00> [00:00:07.150,604] <inf> app: Before updateDisplay()
00> [00:00:07.362,548] <inf> app: Before sleep
00> [00:00:07.632,659] <inf> app: After sleep
00> [00:00:07.632,690] <inf> app: Execution cycle: 7
00> [00:00:07.632,690] <inf> app: Before updateBike()
00> [00:00:07.650,115] <inf> app: Before getBikeData()
00> [00:00:07.650,146] <inf> app: Before cscs notify
00> [00:00:07.650,146] <inf> app: Before cps notify
00> [00:00:07.650,146] <inf> app: Before ftms bike data notify
00> [00:00:07.650,177] <inf> app: Before ftms status notify
00> [00:00:07.650,177] <inf> app: Before updateDisplay()
00> [00:00:07.862,182] <inf> app: Before sleep
00> [00:00:08.132,293] <inf> app: After sleep
00> [00:00:08.132,293] <inf> app: Execution cycle: 8
00> [00:00:08.132,324] <inf> app: Before updateBike()
00> [00:00:08.149,566] <inf> app: Before getBikeData()
00> [00:00:08.149,597] <inf> app: Before cscs notify
00> [00:00:08.149,597] <inf> app: Before cps notify
00> [00:00:08.149,627] <inf> app: Before ftms bike data notify
00> [00:00:08.149,627] <inf> app: Before ftms status notify
00> [00:00:08.149,658] <inf> app: Before updateDisplay()
00> [00:00:08.361,511] <inf> app: Before sleep
00> [00:00:08.632,629] <inf> app: After sleep
00> [00:00:08.632,629] <inf> app: Execution cycle: 9
00> [00:00:08.632,659] <inf> app: Before updateBike()
00> [00:00:08.650,299] <inf> app: Before getBikeData()
00> [00:00:08.650,329] <inf> app: Before cscs notify
00> [00:00:08.650,329] <inf> app: Before cps notify
00> [00:00:08.650,329] <inf> app: Before ftms bike data notify
00> [00:00:08.650,360] <inf> app: Before ftms status notify
00> [00:00:08.650,360] <inf> app: Before updateDisplay()
00> [00:00:08.862,548] <inf> app: Before sleep
00> [00:00:09.132,659] <inf> app: After sleep
00> [00:00:09.132,690] <inf> app: Execution cycle: 10
00> [00:00:09.132,690] <inf> app: Before updateBike()
00> [00:00:09.150,604] <inf> app: Before getBikeData()
00> [00:00:09.150,634] <inf> app: Before cscs notify
00> [00:00:09.150,634] <inf> app: Before cps notify
00> [00:00:09.150,634] <inf> app: Before ftms bike data notify
00> [00:00:09.150,665] <inf> app: Before ftms status notify
00> [00:00:09.150,665] <inf> app: Before updateDisplay()
00> [00:00:09.362,945] <inf> app: Before sleep
00> [00:00:09.633,026] <inf> app: After sleep
00> [00:00:09.633,056] <inf> app: Execution cycle: 11
00> [00:00:09.633,056] <inf> app: Before updateBike()
00> [00:00:09.650,482] <inf> app: Before getBikeData()
00> [00:00:09.650,512] <inf> app: Before cscs notify
00> [00:00:09.650,512] <inf> app: Before cps notify
00> [00:00:09.650,543] <inf> app: Before ftms bike data notify
00> [00:00:09.650,543] <inf> app: Before ftms status notify
00> [00:00:09.650,543] <inf> app: Before updateDisplay()
00> [00:00:09.862,640] <inf> app: Before sleep
00> [00:00:10.133,728] <inf> app: After sleep
00> [00:00:10.133,728] <inf> app: Execution cycle: 12
00> [00:00:10.133,758] <inf> app: Before updateBike()
00> [00:00:10.151,977] <inf> app: Before getBikeData()
00> [00:00:10.152,008] <inf> app: Before cscs notify
00> [00:00:10.152,008] <inf> app: Before cps notify
00> [00:00:10.152,008] <inf> app: Before ftms bike data notify
00> [00:00:10.152,038] <inf> app: Before ftms status notify
00> [00:00:10.152,038] <inf> app: Before updateDisplay()
00> [00:00:10.364,227] <inf> app: Before sleep
00> [00:00:10.633,331] <inf> app: After sleep
00> [00:00:10.633,331] <inf> app: Execution cycle: 13
00> [00:00:10.633,361] <inf> app: Before updateBike()
00> [00:00:10.651,428] <inf> app: Before getBikeData()
00> [00:00:10.651,458] <inf> app: Before cscs notify
00> [00:00:10.651,458] <inf> app: Before cps notify
00> [00:00:10.651,458] <inf> app: Before ftms bike data notify
00> [00:00:10.651,489] <inf> app: Before ftms status notify
00> [00:00:10.651,489] <inf> app: Before updateDisplay()
00> [00:00:10.863,769] <inf> app: Before sleep
00> [00:00:11.133,880] <inf> app: After sleep
00> [00:00:11.133,911] <inf> app: Execution cycle: 14
00> [00:00:11.133,911] <inf> app: Before updateBike()
00> [00:00:11.152,160] <inf> app: Before getBikeData()
00> [00:00:11.152,191] <inf> app: Before cscs notify
00> [00:00:11.152,191] <inf> app: Before cps notify
00> [00:00:11.152,191] <inf> app: Before ftms bike data notify
00> [00:00:11.152,221] <inf> app: Before ftms status notify
00> [00:00:11.152,221] <inf> app: Before updateDisplay()
00> [00:00:11.364,532] <inf> app: Before sleep
00> [00:00:11.633,666] <inf> app: After sleep
00> [00:00:11.633,697] <inf> app: Execution cycle: 15
00> [00:00:11.633,697] <inf> app: Before updateBike()
00> [00:00:11.651,611] <inf> app: Before getBikeData()
00> [00:00:11.651,641] <inf> app: Before cscs notify
00> [00:00:11.651,641] <inf> app: Before cps notify
00> [00:00:11.651,672] <inf> app: Before ftms bike data notify
00> [00:00:11.651,672] <inf> app: Before ftms status notify
00> [00:00:11.651,672] <inf> app: Before updateDisplay()
00> [00:00:11.863,952] <inf> app: Before sleep
00> [00:00:12.134,063] <inf> app: After sleep
00> [00:00:12.134,063] <inf> app: Execution cycle: 16
00> [00:00:12.134,094] <inf> app: Before updateBike()
00> [00:00:12.151,916] <inf> app: Before getBikeData()
00> [00:00:12.151,947] <inf> app: Before cscs notify
00> [00:00:12.151,947] <inf> app: Before cps notify
00> [00:00:12.151,977] <inf> app: Before ftms bike data notify
00> [00:00:12.151,977] <inf> app: Before ftms status notify
00> [00:00:12.152,008] <inf> app: Before updateDisplay()
00> [00:00:12.364,074] <inf> app: Before sleep
00> [00:00:12.634,216] <inf> app: After sleep
00> [00:00:12.634,216] <inf> app: Execution cycle: 17
00> [00:00:12.634,216] <inf> app: Before updateBike()
00> [00:00:12.651,794] <inf> app: Before getBikeData()
00> [00:00:12.651,824] <inf> app: Before cscs notify
00> [00:00:12.651,824] <inf> app: Before cps notify
00> [00:00:12.651,824] <inf> app: Before ftms bike data notify
00> [00:00:12.651,855] <inf> app: Before ftms status notify
00> [00:00:12.651,855] <inf> app: Before updateDisplay()
00> [00:00:12.863,525] <inf> app: Before sleep
00> [00:00:13.134,643] <inf> app: After sleep
00> [00:00:13.134,674] <inf> app: Execution cycle: 18
00> [00:00:13.134,674] <inf> app: Before updateBike()
00> [00:00:13.152,160] <inf> app: Before getBikeData()
00> [00:00:13.152,191] <inf> app: Before cscs notify
00> [00:00:13.152,191] <inf> app: Before cps notify
00> [00:00:13.152,191] <inf> app: Before ftms bike data notify
00> [00:00:13.152,221] <inf> app: Before ftms status notify
00> [00:00:13.152,221] <inf> app: Before updateDisplay()
00> [00:00:13.364,562] <inf> app: Before sleep
00> [00:00:13.634,643] <inf> app: After sleep
00> [00:00:13.634,674] <inf> app: Execution cycle: 19
00> [00:00:13.634,674] <inf> app: Before updateBike()
00> [00:00:13.652,893] <inf> app: Before getBikeData()
00> [00:00:13.652,923] <inf> app: Before cscs notify
00> [00:00:13.652,923] <inf> app: Before cps notify
00> [00:00:13.652,954] <inf> app: Before ftms bike data notify
00> [00:00:13.652,954] <inf> app: Before ftms status notify
00> [00:00:13.652,954] <inf> app: Before updateDisplay()
00> [00:00:13.865,722] <inf> app: Before sleep
00> [00:00:14.134,826] <inf> app: After sleep
00> [00:00:14.134,826] <inf> app: Execution cycle: 20
00> [00:00:14.134,857] <inf> app: Before updateBike()
00> [00:00:14.152,343] <inf> app: Before getBikeData()
00> [00:00:14.152,374] <inf> app: Before cscs notify
00> [00:00:14.152,374] <inf> app: Before cps notify
00> [00:00:14.152,404] <inf> app: Before ftms bike data notify
00> [00:00:14.152,404] <inf> app: Before ftms status notify
00> [00:00:14.152,435] <inf> app: Before updateDisplay()
00> [00:00:14.364,257] <inf> app: Before sleep
00> [00:00:14.634,338] <inf> app: After sleep
00> [00:00:14.634,338] <inf> app: Execution cycle: 21
00> [00:00:14.634,368] <inf> app: Before updateBike()
00> [00:00:14.651,794] <inf> app: Before getBikeData()
00> [00:00:14.651,824] <inf> app: Before cscs notify
00> [00:00:14.651,824] <inf> app: Before cps notify
00> [00:00:14.651,824] <inf> app: Before ftms bike data notify
00> [00:00:14.651,855] <inf> app: Before ftms status notify
00> [00:00:14.651,855] <inf> app: Before updateDisplay()
00> [00:00:14.864,135] <inf> app: Before sleep
00> [00:00:15.134,246] <inf> app: After sleep
00> [00:00:15.134,277] <inf> app: Execution cycle: 22
00> [00:00:15.134,277] <inf> app: Before updateBike()
00> [00:00:15.152,526] <inf> app: Before getBikeData()
00> [00:00:15.152,557] <inf> app: Before cscs notify
00> [00:00:15.152,557] <inf> app: Before cps notify
00> [00:00:15.152,557] <inf> app: Before ftms bike data notify
00> [00:00:15.152,587] <inf> app: Before ftms status notify
00> [00:00:15.152,587] <inf> app: Before updateDisplay()
00> [00:00:15.364,593] <inf> app: Before sleep
00> [00:00:15.634,674] <inf> app: After sleep
00> [00:00:15.634,704] <inf> app: Execution cycle: 23
00> [00:00:15.634,704] <inf> app: Before updateBike()
00> [00:00:15.652,069] <inf> app: Before getBikeData()
00> [00:00:15.652,099] <inf> app: Before cscs notify
00> [00:00:15.652,099] <inf> app: Before cps notify
00> [00:00:15.652,130] <inf> app: Before ftms bike data notify
00> [00:00:15.652,130] <inf> app: Before ftms status notify
00> [00:00:15.652,130] <inf> app: Before updateDisplay()
00> [00:00:15.864,440] <inf> app: Before sleep
00> [00:00:16.134,552] <inf> app: After sleep
00> [00:00:16.134,552] <inf> app: Execution cycle: 24
00> [00:00:16.134,582] <inf> app: Before updateBike()
00> [00:00:16.152,801] <inf> app: Before getBikeData()
00> [00:00:16.152,832] <inf> app: Before cscs notify
00> [00:00:16.152,832] <inf> app: Before cps notify
00> [00:00:16.152,862] <inf> app: Before ftms bike data notify
00> [00:00:16.152,862] <inf> app: Before ftms status notify
00> [00:00:16.152,893] <inf> app: Before updateDisplay()
00> [00:00:16.365,142] <inf> app: Before sleep
00> [00:00:16.634,307] <inf> app: After sleep
00> [00:00:16.634,307] <inf> app: Execution cycle: 25
00> [00:00:16.634,338] <inf> app: Before updateBike()
00> [00:00:16.652,252] <inf> app: Before getBikeData()
00> [00:00:16.652,282] <inf> app: Before cscs notify
00> [00:00:16.652,282] <inf> app: Before cps notify
00> [00:00:16.652,282] <inf> app: Before ftms bike data notify
00> [00:00:16.652,313] <inf> app: Before ftms status notify
00> [00:00:16.652,313] <inf> app: Before updateDisplay()
00> [00:00:16.864,624] <inf> app: Before sleep
00> [00:00:17.134,735] <inf> app: After sleep
00> [00:00:17.134,765] <inf> app: Execution cycle: 26
00> [00:00:17.134,765] <inf> app: Before updateBike()
00> [00:00:17.152,557] <inf> app: Before getBikeData()
00> [00:00:17.152,587] <inf> app: Before cscs notify
00> [00:00:17.152,587] <inf> app: Before cps notify
00> [00:00:17.152,587] <inf> app: Before ftms bike data notify
00> [00:00:17.152,618] <inf> app: Before ftms status notify
00> [00:00:17.152,618] <inf> app: Before updateDisplay()
00> [00:00:17.364,624] <inf> app: Before sleep
00> [00:00:17.634,704] <inf> app: After sleep
00> [00:00:17.634,735] <inf> app: Execution cycle: 27
00> [00:00:17.634,735] <inf> app: Before updateBike()
00> [00:00:17.652,435] <inf> app: Before getBikeData()
00> [00:00:17.652,465] <inf> app: Before cscs notify
00> [00:00:17.652,465] <inf> app: Before cps notify
00> [00:00:17.652,496] <inf> app: Before ftms bike data notify
00> [00:00:17.652,496] <inf> app: Before ftms status notify
00> [00:00:17.652,496] <inf> app: Before updateDisplay()
00> [00:00:17.864,776] <inf> app: Before sleep
00> [00:00:18.134,887] <inf> app: After sleep
00> [00:00:18.134,887] <inf> app: Execution cycle: 28
00> [00:00:18.134,918] <inf> app: Before updateBike()
00> [00:00:18.152,832] <inf> app: Before getBikeData()
00> [00:00:18.152,862] <inf> app: Before cscs notify
00> [00:00:18.152,862] <inf> app: Before cps notify
00> [00:00:18.152,893] <inf> app: Before ftms bike data notify
00> [00:00:18.152,893] <inf> app: Before ftms status notify
00> [00:00:18.152,893] <inf> app: Before updateDisplay()
00> [00:00:18.365,020] <inf> app: Before sleep
00> [00:00:18.634,094] <inf> app: After sleep
00> [00:00:18.634,094] <inf> app: Execution cycle: 29
00> [00:00:18.634,124] <inf> app: Before updateBike()
00> [00:00:18.651,428] <inf> app: Before getBikeData()
00> [00:00:18.651,458] <inf> app: Before cscs notify
00> [00:00:18.651,458] <inf> app: Before cps notify
00> [00:00:18.651,458] <inf> app: Before ftms bike data notify
00> [00:00:18.651,489] <inf> app: Before ftms status notify
00> [00:00:18.651,489] <inf> app: Before updateDisplay()
00> [00:00:18.710,845] <inf> app: Connected
00> [00:00:18.864,715] <inf> app: Before sleep
00> [00:00:19.134,826] <inf> app: After sleep
00> [00:00:19.134,826] <inf> app: Execution cycle: 30
00> [00:00:19.134,857] <inf> app: Before updateBike()
00> [00:00:19.152,160] <inf> app: Before getBikeData()
00> [00:00:19.152,191] <inf> app: Before cscs notify
00> [00:00:19.152,191] <inf> app: Before cps notify
00> [00:00:19.152,191] <inf> app: Before ftms bike data notify
00> [00:00:19.152,221] <inf> app: Before ftms status notify
00> [00:00:19.152,221] <inf> app: Before updateDisplay()
00> [00:00:19.364,135] <inf> app: Before sleep
00> [00:00:19.634,246] <inf> app: After sleep
00> [00:00:19.634,277] <inf> app: Execution cycle: 31
00> [00:00:19.634,277] <inf> app: Before updateBike()
00> [00:00:19.651,611] <inf> app: Before getBikeData()
00> [00:00:19.651,641] <inf> app: Before cscs notify
00> [00:00:19.651,641] <inf> app: Before cps notify
00> [00:00:19.651,641] <inf> app: Before ftms bike data notify
00> [00:00:19.651,672] <inf> app: Before ftms status notify
00> [00:00:19.651,672] <inf> app: Before updateDisplay()
00> [00:00:19.864,227] <inf> app: Before sleep
00> [00:00:20.134,338] <inf> app: After sleep
00> [00:00:20.134,338] <inf> app: Execution cycle: 32
00> [00:00:20.134,368] <inf> app: Before updateBike()
00> [00:00:20.152,343] <inf> app: Before getBikeData()
00> [00:00:20.152,374] <inf> app: Before cscs notify
00> [00:00:20.152,374] <inf> app: Before cps notify
00> [00:00:20.152,404] <inf> app: Before ftms bike data notify
00> [00:00:20.152,404] <inf> app: Before ftms status notify
00> [00:00:20.152,404] <inf> app: Before updateDisplay()
00> [00:00:20.364,501] <inf> app: Before sleep
00> [00:00:20.634,613] <inf> app: After sleep
00> [00:00:20.634,643] <inf> app: Execution cycle: 33
00> [00:00:20.634,643] <inf> app: Before updateBike()
00> [00:00:20.652,679] <inf> app: Before getBikeData()
00> [00:00:20.652,709] <inf> app: Before cscs notify
00> [00:00:20.652,709] <inf> app: Before cps notify
00> [00:00:20.652,709] <inf> app: Before ftms bike data notify
00> [00:00:20.652,740] <inf> app: Before ftms status notify
00> [00:00:20.652,740] <inf> app: Before updateDisplay()
00> [00:00:20.865,081] <inf> app: Before sleep
00> [00:00:21.134,185] <inf> app: After sleep
00> [00:00:21.134,185] <inf> app: Execution cycle: 34
00> [00:00:21.134,216] <inf> app: Before updateBike()
00> [00:00:21.152,130] <inf> app: Before getBikeData()
00> [00:00:21.152,160] <inf> app: Before cscs notify
00> [00:00:21.152,160] <inf> app: Before cps notify
00> [00:00:21.152,160] <inf> app: Before ftms bike data notify
00> [00:00:21.152,191] <inf> app: Before ftms status notify
00> [00:00:21.152,191] <inf> app: Before updateDisplay()
00> [00:00:21.364,318] <inf> app: Before sleep
00> [00:00:21.634,490] <inf> app: After sleep
00> [00:00:21.634,521] <inf> app: Execution cycle: 35
00> [00:00:21.634,521] <inf> app: Before updateBike()
00> [00:00:21.652,008] <inf> app: Before getBikeData()
00> [00:00:21.652,038] <inf> app: Before cscs notify
00> [00:00:21.652,038] <inf> app: Before cps notify
00> [00:00:21.652,038] <inf> app: Before ftms bike data notify
00> [00:00:21.652,069] <inf> app: Before ftms status notify
00> [00:00:21.652,069] <inf> app: Before updateDisplay()
00> [00:00:21.864,776] <inf> app: Before sleep
00> [00:00:22.134,857] <inf> app: After sleep
00> [00:00:22.134,887] <inf> app: Execution cycle: 36
00> [00:00:22.134,887] <inf> app: Before updateBike()
00> [00:00:22.152,313] <inf> app: Before getBikeData()
00> [00:00:22.152,343] <inf> app: Before cscs notify
00> [00:00:22.152,343] <inf> app: Before cps notify
00> [00:00:22.152,374] <inf> app: Before ftms bike data notify
00> [00:00:22.152,374] <inf> app: Before ftms status notify
00> [00:00:22.152,374] <inf> app: Before updateDisplay()
00> [00:00:22.364,440] <inf> app: Before sleep
00> [00:00:22.634,521] <inf> app: After sleep
00> [00:00:22.634,521] <inf> app: Execution cycle: 37
00> [00:00:22.634,552] <inf> app: Before updateBike()
00> [00:00:22.651,763] <inf> app: Before getBikeData()
00> [00:00:22.651,794] <inf> app: Before cscs notify
00> [00:00:22.651,794] <inf> app: Before cps notify
00> [00:00:22.651,824] <inf> app: Before ftms bike data notify
00> [00:00:22.651,824] <inf> app: Before ftms status notify
00> [00:00:22.651,855] <inf> app: Before updateDisplay()
00> [00:00:22.864,227] <inf> app: Before sleep
00> [00:00:23.134,338] <inf> app: After sleep
00> [00:00:23.134,338] <inf> app: Execution cycle: 38
00> [00:00:23.134,368] <inf> app: Before updateBike()
00> [00:00:23.151,641] <inf> app: Before getBikeData()
00> [00:00:23.151,672] <inf> app: Before cscs notify
00> [00:00:23.151,672] <inf> app: Before cps notify
00> [00:00:23.151,672] <inf> app: Before ftms bike data notify
00> [00:00:23.151,702] <inf> app: Before ftms status notify
00> [00:00:23.151,702] <inf> app: Before updateDisplay()
00> [00:00:23.363,952] <inf> app: Before sleep
00> [00:00:23.635,070] <inf> app: After sleep
00> [00:00:23.635,101] <inf> app: Execution cycle: 39
00> [00:00:23.635,101] <inf> app: Before updateBike()
00> [00:00:23.653,289] <inf> app: Before getBikeData()
00> [00:00:23.653,289] <inf> app: Before cscs notify
00> [00:00:23.653,320] <inf> app: Before cps notify
00> [00:00:23.653,320] <inf> app: Before ftms bike data notify
00> [00:00:23.653,350] <inf> app: Before ftms status notify
00> [00:00:23.653,350] <inf> app: Before updateDisplay()
00> [00:00:23.866,302] <inf> app: Before sleep
00> [00:00:24.135,406] <inf> app: After sleep
00> [00:00:24.135,437] <inf> app: Execution cycle: 40
00> [00:00:24.135,437] <inf> app: Before updateBike()
00> [00:00:24.152,740] <inf> app: Before getBikeData()
00> [00:00:24.152,770] <inf> app: Before cscs notify
00> [00:00:24.152,770] <inf> app: Before cps notify
00> [00:00:24.152,801] <inf> app: Before ftms bike data notify
00> [00:00:24.152,801] <inf> app: Before ftms status notify
00> [00:00:24.152,801] <inf> app: Before updateDisplay()
00> [00:00:24.364,990] <inf> app: Before sleep
00> [00:00:24.635,101] <inf> app: After sleep
00> [00:00:24.635,101] <inf> app: Execution cycle: 41
00> [00:00:24.635,131] <inf> app: Before updateBike()
00> [00:00:24.653,045] <inf> app: Before getBikeData()
00> [00:00:24.653,076] <inf> app: Before cscs notify
00> [00:00:24.653,076] <inf> app: Before cps notify
00> [00:00:24.653,106] <inf> app: Before ftms bike data notify
00> [00:00:24.653,106] <inf> app: Before ftms status notify
00> [00:00:24.653,137] <inf> app: Before updateDisplay()
00> [00:00:24.865,844] <inf> app: Before sleep
00> [00:00:25.135,955] <inf> app: After sleep
00> [00:00:25.135,955] <inf> app: Execution cycle: 42
00> [00:00:25.135,986] <inf> app: Before updateBike()
00> [00:00:25.153,778] <inf> app: Before getBikeData()
00> [00:00:25.153,808] <inf> app: Before cscs notify
00> [00:00:25.153,808] <inf> app: Before cps notify
00> [00:00:25.153,808] <inf> app: Before ftms bike data notify
00> [00:00:25.153,839] <inf> app: Before ftms status notify
00> [00:00:25.153,839] <inf> app: Before updateDisplay()
00> [00:00:25.366,149] <inf> app: Before sleep
00> [00:00:25.635,284] <inf> app: After sleep
00> [00:00:25.635,314] <inf> app: Execution cycle: 43
00> [00:00:25.635,314] <inf> app: Before updateBike()
00> [00:00:25.653,228] <inf> app: Before getBikeData()
00> [00:00:25.653,259] <inf> app: Before cscs notify
00> [00:00:25.653,259] <inf> app: Before cps notify
00> [00:00:25.653,259] <inf> app: Before ftms bike data notify
00> [00:00:25.653,289] <inf> app: Before ftms status notify
00> [00:00:25.653,289] <inf> app: Before updateDisplay()
00> [00:00:25.865,844] <inf> app: Before sleep
00> [00:00:26.135,955] <inf> app: After sleep
00> [00:00:26.135,955] <inf> app: Execution cycle: 44
00> [00:00:26.135,986] <inf> app: Before updateBike()
00> [00:00:26.153,778] <inf> app: Before getBikeData()
00> [00:00:26.153,808] <inf> app: Before cscs notify
00> [00:00:26.153,808] <inf> app: Before cps notify
00> [00:00:26.153,808] <inf> app: Before ftms bike data notify
00> [00:00:26.153,839] <inf> app: Before ftms status notify
00> [00:00:26.153,839] <inf> app: Before updateDisplay()
00> [00:00:26.365,936] <inf> app: Before sleep
00> [00:00:26.636,016] <inf> app: After sleep
00> [00:00:26.636,016] <inf> app: Execution cycle: 45
00> [00:00:26.636,047] <inf> app: Before updateBike()
00> [00:00:26.653,656] <inf> app: Before getBikeData()
00> [00:00:26.653,686] <inf> app: Before cscs notify
00> [00:00:26.653,686] <inf> app: Before cps notify
00> [00:00:26.653,717] <inf> app: Before ftms bike data notify
00> [00:00:26.653,717] <inf> app: Before ftms status notify
00> [00:00:26.653,747] <inf> app: Before updateDisplay()
00> [00:00:26.865,997] <inf> app: Before sleep
00> [00:00:27.136,108] <inf> app: After sleep
00> [00:00:27.136,108] <inf> app: Execution cycle: 46
00> [00:00:27.136,138] <inf> app: Before updateBike()
00> [00:00:27.153,961] <inf> app: Before getBikeData()
00> [00:00:27.153,991] <inf> app: Before cscs notify
00> [00:00:27.153,991] <inf> app: Before cps notify
00> [00:00:27.153,991] <inf> app: Before ftms bike data notify
00> [00:00:27.154,022] <inf> app: Before ftms status notify
00> [00:00:27.154,022] <inf> app: Before updateDisplay()
00> [00:00:27.365,997] <inf> app: Before sleep
00> [00:00:27.636,108] <inf> app: After sleep
00> [00:00:27.636,138] <inf> app: Execution cycle: 47
00> [00:00:27.636,138] <inf> app: Before updateBike()
00> [00:00:27.653,839] <inf> app: Before getBikeData()
00> [00:00:27.653,869] <inf> app: Before cscs notify
00> [00:00:27.653,869] <inf> app: Before cps notify
00> [00:00:27.653,869] <inf> app: Before ftms bike data notify
00> [00:00:27.653,900] <inf> app: Before ftms status notify
00> [00:00:27.653,900] <inf> app: Before updateDisplay()
00> [00:00:27.866,516] <inf> app: Before sleep
00> [00:00:27.901,641] <inf> app: Disconnected (reason 0x28)
00> [00:00:28.136,627] <inf> app: After sleep
00> [00:00:28.136,657] <inf> app: Execution cycle: 48
00> [00:00:28.136,657] <inf> app: Before updateBike()
00> [00:00:28.154,144] <inf> app: Before getBikeData()
00> [00:00:28.154,174] <inf> app: Before cscs notify
00> [00:00:28.154,174] <inf> app: Before cps notify
00> [00:00:28.154,174] <inf> app: Before ftms bike data notify
00> [00:00:28.154,205] <inf> app: Before ftms status notify
00> [00:00:28.154,205] <inf> app: Before updateDisplay()
00> [00:00:28.366,058] <inf> app: Before sleep
00> [00:00:28.636,169] <inf> app: After sleep
00> [00:00:28.636,199] <inf> app: Execution cycle: 49
00> [00:00:28.636,199] <inf> app: Before updateBike()
00> [00:00:28.653,961] <inf> app: Before getBikeData()
00> [00:00:28.653,991] <inf> app: Before cscs notify
00> [00:00:28.653,991] <inf> app: Before cps notify
00> [00:00:28.653,991] <inf> app: Before ftms bike data notify
00> [00:00:28.654,022] <inf> app: Before ftms status notify
00> [00:00:28.654,022] <inf> app: Before updateDisplay()
00> [00:00:28.865,936] <inf> app: Before sleep
00> [00:00:29.137,023] <inf> app: After sleep
00> [00:00:29.137,023] <inf> app: Execution cycle: 50
00> [00:00:29.137,054] <inf> app: Before updateBike()
00> [00:00:29.154,266] <inf> app: Before getBikeData()
00> [00:00:29.154,296] <inf> app: Before cscs notify
00> [00:00:29.154,296] <inf> app: Before cps notify
00> [00:00:29.154,327] <inf> app: Before ftms bike data notify
00> [00:00:29.154,327] <inf> app: Before ftms status notify
00> [00:00:29.154,357] <inf> app: Before updateDisplay()
00> [00:00:29.366,607] <inf> app: Before sleep
00> [00:00:29.637,725] <inf> app: After sleep
00> [00:00:29.637,725] <inf> app: Execution cycle: 51
00> [00:00:29.637,756] <inf> app: Before updateBike()
00> [00:00:29.655,853] <inf> app: Before getBikeData()
00> [00:00:29.655,883] <inf> app: Before cscs notify
00> [00:00:29.655,883] <inf> app: Before cps notify
00> [00:00:29.655,883] <inf> app: Before ftms bike data notify
00> [00:00:29.655,914] <inf> app: Before ftms status notify
00> [00:00:29.655,914] <inf> app: Before updateDisplay()
00> [00:00:29.868,255] <inf> app: Before sleep
00> [00:00:30.137,359] <inf> app: After sleep
00> [00:00:30.137,390] <inf> app: Execution cycle: 52
00> [00:00:30.137,390] <inf> app: Before updateBike()
00> [00:00:30.155,303] <inf> app: Before getBikeData()
00> [00:00:30.155,334] <inf> app: Before cscs notify
00> [00:00:30.155,334] <inf> app: Before cps notify
00> [00:00:30.155,334] <inf> app: Before ftms bike data notify
00> [00:00:30.155,364] <inf> app: Before ftms status notify
00> [00:00:30.155,364] <inf> app: Before updateDisplay()
00> [00:00:30.367,675] <inf> app: Before sleep
00> [00:00:30.637,786] <inf> app: After sleep
00> [00:00:30.637,817] <inf> app: Execution cycle: 53
00> [00:00:30.637,817] <inf> app: Before updateBike()
00> [00:00:30.656,036] <inf> app: Before getBikeData()
00> [00:00:30.656,066] <inf> app: Before cscs notify
00> [00:00:30.656,066] <inf> app: Before cps notify
00> [00:00:30.656,097] <inf> app: Before ftms bike data notify
00> [00:00:30.656,097] <inf> app: Before ftms status notify
00> [00:00:30.656,097] <inf> app: Before updateDisplay()
00> [00:00:30.867,950] <inf> app: Before sleep
00> [00:00:31.138,061] <inf> app: After sleep
00> [00:00:31.138,061] <inf> app: Execution cycle: 54
00> [00:00:31.138,092] <inf> app: Before updateBike()
00> [00:00:31.153,106] <inf> app: Before getBikeData()
00> [00:00:31.153,137] <inf> app: Before cscs notify
00> [00:00:31.153,137] <inf> app: Before cps notify
00> [00:00:31.153,167] <inf> app: Before ftms bike data notify
00> [00:00:31.153,167] <inf> app: Before ftms status notify
00> [00:00:31.153,198] <inf> app: Before updateDisplay()
00> [00:00:31.365,447] <inf> app: Before sleep
00> [00:00:31.638,549] <inf> app: After sleep
00> [00:00:31.638,549] <inf> app: Execution cycle: 55
00> [00:00:31.638,580] <inf> app: Before updateBike()
00> [00:00:31.656,066] <inf> app: Before getBikeData()
00> [00:00:31.656,097] <inf> app: Before cscs notify
00> [00:00:31.656,097] <inf> app: Before cps notify
00> [00:00:31.656,097] <inf> app: Before ftms bike data notify
00> [00:00:31.656,127] <inf> app: Before ftms status notify
00> [00:00:31.656,127] <inf> app: Before updateDisplay()
00> [00:00:31.868,438] <inf> app: Before sleep
00> [00:00:32.138,549] <inf> app: After sleep
00> [00:00:32.138,580] <inf> app: Execution cycle: 56
00> [00:00:32.138,580] <inf> app: Before updateBike()
00> [00:00:32.156,372] <inf> app: Before getBikeData()
00> [00:00:32.156,402] <inf> app: Before cscs notify
00> [00:00:32.156,402] <inf> app: Before cps notify
00> [00:00:32.156,402] <inf> app: Before ftms bike data notify
00> [00:00:32.156,433] <inf> app: Before ftms status notify
00> [00:00:32.156,433] <inf> app: Before updateDisplay()
00> [00:00:32.368,621] <inf> app: Before sleep
00> [00:00:32.638,732] <inf> app: After sleep
00> [00:00:32.638,763] <inf> app: Execution cycle: 57
00> [00:00:32.638,763] <inf> app: Before updateBike()
00> [00:00:32.655,822] <inf> app: Before getBikeData()
00> [00:00:32.655,853] <inf> app: Before cscs notify
00> [00:00:32.655,853] <inf> app: Before cps notify
00> [00:00:32.655,883] <inf> app: Before ftms bike data notify
00> [00:00:32.655,883] <inf> app: Before ftms status notify
00> [00:00:32.655,883] <inf> app: Before updateDisplay()
00> [00:00:32.867,584] <inf> app: Before sleep
00> [00:00:33.138,671] <inf> app: After sleep
00> [00:00:33.138,671] <inf> app: Execution cycle: 58
00> [00:00:33.138,702] <inf> app: Before updateBike()
00> [00:00:33.156,555] <inf> app: Before getBikeData()
00> [00:00:33.156,585] <inf> app: Before cscs notify
00> [00:00:33.156,585] <inf> app: Before cps notify
00> [00:00:33.156,616] <inf> app: Before ftms bike data notify
00> [00:00:33.156,616] <inf> app: Before ftms status notify
00> [00:00:33.156,616] <inf> app: Before updateDisplay()
00> [00:00:33.368,530] <inf> app: Before sleep
00> [00:00:33.638,641] <inf> app: After sleep
00> [00:00:33.638,641] <inf> app: Execution cycle: 59
00> [00:00:33.638,671] <inf> app: Before updateBike()
00> [00:00:33.656,005] <inf> app: Before getBikeData()
00> [00:00:33.656,005] <inf> app: Before cscs notify
00> [00:00:33.656,036] <inf> app: Before cps notify
00> [00:00:33.656,036] <inf> app: Before ftms bike data notify
00> [00:00:33.656,066] <inf> app: Before ftms status notify
00> [00:00:33.656,066] <inf> app: Before updateDisplay()
00> [00:00:33.868,286] <inf> app: Before sleep
00> [00:00:34.138,366] <inf> app: After sleep
00> [00:00:34.138,397] <inf> app: Execution cycle: 60
00> [00:00:34.138,397] <inf> app: Before updateBike()
00> [00:00:34.156,402] <inf> app: Before getBikeData()
00> [00:00:34.156,402] <inf> app: Before cscs notify
00> [00:00:34.156,433] <inf> app: Before cps notify
00> [00:00:34.156,433] <inf> app: Before ftms bike data notify
00> [00:00:34.156,463] <inf> app: Before ftms status notify
00> [00:00:34.156,463] <inf> app: Before updateDisplay()
00> [00:00:34.368,560] <inf> app: Before sleep
00> [00:00:34.638,671] <inf> app: After sleep
00> [00:00:34.638,702] <inf> app: Execution cycle: 61
00> [00:00:34.638,702] <inf> app: Before updateBike()
00> [00:00:34.655,853] <inf> app: Before getBikeData()
00> [00:00:34.655,883] <inf> app: Before cscs notify
00> [00:00:34.655,883] <inf> app: Before cps notify
00> [00:00:34.655,914] <inf> app: Before ftms bike data notify
00> [00:00:34.655,914] <inf> app: Before ftms status notify
00> [00:00:34.655,914] <inf> app: Before updateDisplay()
00> [00:00:34.867,584] <inf> app: Before sleep
00> [00:00:35.138,702] <inf> app: After sleep
00> [00:00:35.138,702] <inf> app: Execution cycle: 62
00> [00:00:35.138,732] <inf> app: Before updateBike()
00> [00:00:35.156,585] <inf> app: Before getBikeData()
00> [00:00:35.156,616] <inf> app: Before cscs notify
00> [00:00:35.156,616] <inf> app: Before cps notify
00> [00:00:35.156,646] <inf> app: Before ftms bike data notify
00> [00:00:35.156,646] <inf> app: Before ftms status notify
00> [00:00:35.156,646] <inf> app: Before updateDisplay()
00> [00:00:35.368,927] <inf> app: Before sleep
00> [00:00:35.639,038] <inf> app: After sleep
00> [00:00:35.639,038] <inf> app: Execution cycle: 63
00> [00:00:35.639,068] <inf> app: Before updateBike()
00> [00:00:35.656,890] <inf> app: Before getBikeData()
00> [00:00:35.656,890] <inf> app: Before cscs notify
00> [00:00:35.656,921] <inf> app: Before cps notify
00> [00:00:35.656,921] <inf> app: Before ftms bike data notify
00> [00:00:35.656,951] <inf> app: Before ftms status notify
00> [00:00:35.656,951] <inf> app: Before updateDisplay()
00> [00:00:35.869,171] <inf> app: Before sleep
00> [00:00:36.139,282] <inf> app: After sleep
00> [00:00:36.139,312] <inf> app: Execution cycle: 64
00> [00:00:36.139,312] <inf> app: Before updateBike()
00> [00:00:36.156,768] <inf> app: Before getBikeData()
00> [00:00:36.156,799] <inf> app: Before cscs notify
00> [00:00:36.156,799] <inf> app: Before cps notify
00> [00:00:36.156,799] <inf> app: Before ftms bike data notify
00> [00:00:36.156,829] <inf> app: Before ftms status notify
00> [00:00:36.156,829] <inf> app: Before updateDisplay()
00> [00:00:36.369,018] <inf> app: Before sleep
00> [00:00:36.639,129] <inf> app: After sleep
00> [00:00:36.639,160] <inf> app: Execution cycle: 65
00> [00:00:36.639,160] <inf> app: Before updateBike()
00> [00:00:36.657,226] <inf> app: Before getBikeData()
00> [00:00:36.657,257] <inf> app: Before cscs notify
00> [00:00:36.657,257] <inf> app: Before cps notify
00> [00:00:36.657,257] <inf> app: Before ftms bike data notify
00> [00:00:36.657,287] <inf> app: Before ftms status notify
00> [00:00:36.657,287] <inf> app: Before updateDisplay()
00> [00:00:36.868,988] <inf> app: Before sleep
00> [00:00:37.140,075] <inf> app: After sleep
00> [00:00:37.140,075] <inf> app: Execution cycle: 66
00> [00:00:37.140,106] <inf> app: Before updateBike()
00> [00:00:37.157,958] <inf> app: Before getBikeData()
00> [00:00:37.157,989] <inf> app: Before cscs notify
00> [00:00:37.157,989] <inf> app: Before cps notify
00> [00:00:37.158,020] <inf> app: Before ftms bike data notify
00> [00:00:37.158,020] <inf> app: Before ftms status notify
00> [00:00:37.158,020] <inf> app: Before updateDisplay()
00> [00:00:37.370,147] <inf> app: Before sleep
00> [00:00:37.640,319] <inf> app: After sleep
00> [00:00:37.640,319] <inf> app: Execution cycle: 67
00> [00:00:37.640,350] <inf> app: Before updateBike()
00> [00:00:37.658,264] <inf> app: Before getBikeData()
00> [00:00:37.658,294] <inf> app: Before cscs notify
00> [00:00:37.658,294] <inf> app: Before cps notify
00> [00:00:37.658,294] <inf> app: Before ftms bike data notify
00> [00:00:37.658,325] <inf> app: Before ftms status notify
00> [00:00:37.658,325] <inf> app: Before updateDisplay()
00> [00:00:37.870,666] <inf> app: Before sleep
00> [00:00:38.140,747] <inf> app: After sleep
00> [00:00:38.140,777] <inf> app: Execution cycle: 68
00> [00:00:38.140,777] <inf> app: Before updateBike()
00> [00:00:38.158,996] <inf> app: Before getBikeData()
00> [00:00:38.159,027] <inf> app: Before cscs notify
00> [00:00:38.159,027] <inf> app: Before cps notify
00> [00:00:38.159,027] <inf> app: Before ftms bike data notify
00> [00:00:38.159,057] <inf> app: Before ftms status notify
00> [00:00:38.159,057] <inf> app: Before updateDisplay()
00> [00:00:38.371,185] <inf> app: Before sleep
00> [00:00:38.640,258] <inf> app: After sleep
00> [00:00:38.640,289] <inf> app: Execution cycle: 69
00> [00:00:38.640,289] <inf> app: Before updateBike()
00> [00:00:38.657,592] <inf> app: Before getBikeData()
00> [00:00:38.657,623] <inf> app: Before cscs notify
00> [00:00:38.657,623] <inf> app: Before cps notify
00> [00:00:38.657,653] <inf> app: Before ftms bike data notify
00> [00:00:38.657,653] <inf> app: Before ftms status notify
00> [00:00:38.657,653] <inf> app: Before updateDisplay()
00> [00:00:38.869,964] <inf> app: Before sleep
00> [00:00:39.141,052] <inf> app: After sleep
00> [00:00:39.141,052] <inf> app: Execution cycle: 70
00> [00:00:39.141,082] <inf> app: Before updateBike()
00> [00:00:39.159,149] <inf> app: Before getBikeData()
00> [00:00:39.159,179] <inf> app: Before cscs notify
00> [00:00:39.159,179] <inf> app: Before cps notify
00> [00:00:39.159,179] <inf> app: Before ftms bike data notify
00> [00:00:39.159,210] <inf> app: Before ftms status notify
00> [00:00:39.159,210] <inf> app: Before updateDisplay()
00> [00:00:39.370,849] <inf> app: Before sleep
00> [00:00:39.641,967] <inf> app: After sleep
00> [00:00:39.641,967] <inf> app: Execution cycle: 71
00> [00:00:39.641,998] <inf> app: Before updateBike()
00> [00:00:39.659,454] <inf> app: Before getBikeData()
00> [00:00:39.659,484] <inf> app: Before cscs notify
00> [00:00:39.659,484] <inf> app: Before cps notify
00> [00:00:39.659,484] <inf> app: Before ftms bike data notify
00> [00:00:39.659,515] <inf> app: Before ftms status notify
00> [00:00:39.659,515] <inf> app: Before updateDisplay()
00> [00:00:39.871,704] <inf> app: Before sleep
00> [00:00:40.141,815] <inf> app: After sleep
00> [00:00:40.141,845] <inf> app: Execution cycle: 72
00> [00:00:40.141,845] <inf> app: Before updateBike()
00> [00:00:40.159,332] <inf> app: Before getBikeData()
00> [00:00:40.159,362] <inf> app: Before cscs notify
00> [00:00:40.159,362] <inf> app: Before cps notify
00> [00:00:40.159,362] <inf> app: Before ftms bike data notify
00> [00:00:40.159,393] <inf> app: Before ftms status notify
00> [00:00:40.159,393] <inf> app: Before updateDisplay()
00> [00:00:40.371,704] <inf> app: Before sleep
00> [00:00:40.641,815] <inf> app: After sleep
00> [00:00:40.641,845] <inf> app: Execution cycle: 73
00> [00:00:40.641,845] <inf> app: Before updateBike()
00> [00:00:40.659,637] <inf> app: Before getBikeData()
00> [00:00:40.659,667] <inf> app: Before cscs notify
00> [00:00:40.659,667] <inf> app: Before cps notify
00> [00:00:40.659,698] <inf> app: Before ftms bike data notify
00> [00:00:40.659,698] <inf> app: Before ftms status notify
00> [00:00:40.659,698] <inf> app: Before updateDisplay()
00> [00:00:40.871,337] <inf> app: Before sleep
00> [00:00:41.141,418] <inf> app: After sleep
00> [00:00:41.141,418] <inf> app: Execution cycle: 74
00> [00:00:41.141,448] <inf> app: Before updateBike()
00> [00:00:41.159,515] <inf> app: Before getBikeData()
00> [00:00:41.159,545] <inf> app: Before cscs notify
00> [00:00:41.159,545] <inf> app: Before cps notify
00> [00:00:41.159,576] <inf> app: Before ftms bike data notify
00> [00:00:41.159,576] <inf> app: Before ftms status notify
00> [00:00:41.159,576] <inf> app: Before updateDisplay()
00> [00:00:41.371,459] <inf> app: Before sleep
00> [00:00:41.641,571] <inf> app: After sleep
00> [00:00:41.641,571] <inf> app: Execution cycle: 75
00> [00:00:41.641,601] <inf> app: Before updateBike()
00> [00:00:41.658,966] <inf> app: Before getBikeData()
00> [00:00:41.658,966] <inf> app: Before cscs notify
00> [00:00:41.658,996] <inf> app: Before cps notify
00> [00:00:41.658,996] <inf> app: Before ftms bike data notify
00> [00:00:41.659,027] <inf> app: Before ftms status notify
00> [00:00:41.659,027] <inf> app: Before updateDisplay()
00> [00:00:41.870,880] <inf> app: Before sleep
00> [00:00:42.141,998] <inf> app: After sleep
00> [00:00:42.142,028] <inf> app: Execution cycle: 76
00> [00:00:42.142,028] <inf> app: Before updateBike()
00> [00:00:42.159,271] <inf> app: Before getBikeData()
00> [00:00:42.159,271] <inf> app: Before cscs notify
00> [00:00:42.159,301] <inf> app: Before cps notify
00> [00:00:42.159,301] <inf> app: Before ftms bike data notify
00> [00:00:42.159,332] <inf> app: Before ftms status notify
00> [00:00:42.159,332] <inf> app: Before updateDisplay()
00> [00:00:42.371,612] <inf> app: Before sleep
00> [00:00:42.641,723] <inf> app: After sleep
00> [00:00:42.641,754] <inf> app: Execution cycle: 77
00> [00:00:42.641,754] <inf> app: Before updateBike()
00> [00:00:42.659,149] <inf> app: Before getBikeData()
00> [00:00:42.659,179] <inf> app: Before cscs notify
00> [00:00:42.659,179] <inf> app: Before cps notify
00> [00:00:42.659,210] <inf> app: Before ftms bike data notify
00> [00:00:42.659,210] <inf> app: Before ftms status notify
00> [00:00:42.659,210] <inf> app: Before updateDisplay()
00> [00:00:42.870,727] <inf> app: Before sleep
00> [00:00:43.141,845] <inf> app: After sleep
00> [00:00:43.141,876] <inf> app: Execution cycle: 78
00> [00:00:43.141,876] <inf> app: Before updateBike()
00> [00:00:43.159,454] <inf> app: Before getBikeData()
00> [00:00:43.159,545] <inf> app: Before cscs notify
00> [00:00:43.159,545] <inf> app: Before cps notify
00> [00:00:43.159,576] <inf> app: Before ftms bike data notify
00> [00:00:43.159,576] <inf> app: Before ftms status notify
00> [00:00:43.159,606] <inf> app: Before updateDisplay()
00> [00:00:43.380,920] <inf> app: Before sleep
00> [00:00:43.642,028] <inf> app: After sleep
00> [00:00:43.642,028] <inf> app: Execution cycle: 79
00> [00:00:43.642,059] <inf> app: Before updateBike()
00> [00:00:43.660,186] <inf> app: Before getBikeData()
00> [00:00:43.660,278] <inf> app: Before cscs notify
00> [00:00:43.660,278] <inf> app: Before cps notify
00> [00:00:43.660,308] <inf> app: Before ftms bike data notify
00> [00:00:43.660,308] <inf> app: Before ftms status notify
00> [00:00:43.660,308] <inf> app: Before updateDisplay()
00> [00:00:43.873,168] <inf> app: Before sleep
00> [00:00:44.142,272] <inf> app: After sleep
00> [00:00:44.142,303] <inf> app: Execution cycle: 80
00> [00:00:44.142,303] <inf> app: Before updateBike()
00> [00:00:44.159,637] <inf> app: Before getBikeData()
00> [00:00:44.159,729] <inf> app: Before cscs notify
00> [00:00:44.159,729] <inf> app: Before cps notify
00> [00:00:44.159,759] <inf> app: Before ftms bike data notify
00> [00:00:44.159,759] <inf> app: Before ftms status notify
00> [00:00:44.159,759] <inf> app: Before updateDisplay()
00> [00:00:44.374,114] <inf> app: Before sleep
00> [00:00:44.642,211] <inf> app: After sleep
00> [00:00:44.642,242] <inf> app: Execution cycle: 81
00> [00:00:44.642,242] <inf> app: Before updateBike()
00> [00:00:44.660,064] <inf> app: Before getBikeData()
00> [00:00:44.660,156] <inf> app: Before cscs notify
00> [00:00:44.660,156] <inf> app: Before cps notify
00> [00:00:44.660,186] <inf> app: Before ftms bike data notify
00> [00:00:44.660,186] <inf> app: Before ftms status notify
00> [00:00:44.660,217] <inf> app: Before updateDisplay()
00> [00:00:44.867,706] <inf> app: Before sleep
00> [00:00:45.142,852] <inf> app: After sleep
00> [00:00:45.142,852] <inf> app: Execution cycle: 82
00> [00:00:45.142,883] <inf> app: Before updateBike()
00> [00:00:45.160,797] <inf> app: Before getBikeData()
00> [00:00:45.160,888] <inf> app: Before cscs notify
00> [00:00:45.160,888] <inf> app: Before cps notify
00> [00:00:45.160,919] <inf> app: Before ftms bike data notify
00> [00:00:45.160,919] <inf> app: Before ftms status notify
00> [00:00:45.160,949] <inf> app: Before updateDisplay()
00> [00:00:45.382,171] <inf> app: Before sleep
00> [00:00:45.642,303] <inf> app: After sleep
00> [00:00:45.642,303] <inf> app: Execution cycle: 83
00> [00:00:45.642,333] <inf> app: Before updateBike()
00> [00:00:45.660,247] <inf> app: Before getBikeData()
00> [00:00:45.660,339] <inf> app: Before cscs notify
00> [00:00:45.660,339] <inf> app: Before cps notify
00> [00:00:45.660,369] <inf> app: Before ftms bike data notify
00> [00:00:45.660,369] <inf> app: Before ftms status notify
00> [00:00:45.660,400] <inf> app: Before updateDisplay()
00> [00:00:45.874,420] <inf> app: Before sleep
00> [00:00:46.142,517] <inf> app: After sleep
00> [00:00:46.142,547] <inf> app: Execution cycle: 84
00> [00:00:46.142,578] <inf> app: Before updateBike()
00> [00:00:46.160,125] <inf> app: Before getBikeData()
00> [00:00:46.160,217] <inf> app: Before cscs notify
00> [00:00:46.160,217] <inf> app: Before cps notify
00> [00:00:46.160,247] <inf> app: Before ftms bike data notify
00> [00:00:46.160,247] <inf> app: Before ftms status notify
00> [00:00:46.160,247] <inf> app: Before updateDisplay()
00> [00:00:46.382,537] <inf> app: Before sleep
00> [00:00:46.642,639] <inf> app: After sleep
00> [00:00:46.642,669] <inf> app: Execution cycle: 85
00> [00:00:46.642,669] <inf> app: Before updateBike()
00> [00:00:46.660,430] <inf> app: Before getBikeData()
00> [00:00:46.660,522] <inf> app: Before cscs notify
00> [00:00:46.660,522] <inf> app: Before cps notify
00> [00:00:46.660,552] <inf> app: Before ftms bike data notify
00> [00:00:46.660,552] <inf> app: Before ftms status notify
00> [00:00:46.660,583] <inf> app: Before updateDisplay()
00> [00:00:46.878,509] <inf> app: Before sleep
00> [00:00:47.142,578] <inf> app: After sleep
00> [00:00:47.142,578] <inf> app: Execution cycle: 86
00> [00:00:47.142,608] <inf> app: Before updateBike()
00> [00:00:47.159,912] <inf> app: Before getBikeData()
00> [00:00:47.160,003] <inf> app: Before cscs notify
00> [00:00:47.160,003] <inf> app: Before cps notify
00> [00:00:47.160,034] <inf> app: Before ftms bike data notify
00> [00:00:47.160,034] <inf> app: Before ftms status notify
00> [00:00:47.160,064] <inf> app: Before updateDisplay()
00> [00:00:47.381,683] <inf> app: Before sleep
00> [00:00:47.642,791] <inf> app: After sleep
00> [00:00:47.642,791] <inf> app: Execution cycle: 87
00> [00:00:47.642,822] <inf> app: Before updateBike()
00> [00:00:47.660,644] <inf> app: Before getBikeData()
00> [00:00:47.660,736] <inf> app: Before cscs notify
00> [00:00:47.660,736] <inf> app: Before cps notify
00> [00:00:47.660,766] <inf> app: Before ftms bike data notify
00> [00:00:47.660,766] <inf> app: Before ftms status notify
00> [00:00:47.660,797] <inf> app: Before updateDisplay()
00> [00:00:47.881,774] <inf> app: Before sleep
00> [00:00:48.142,883] <inf> app: After sleep
00> [00:00:48.142,913] <inf> app: Execution cycle: 88
00> [00:00:48.142,913] <inf> app: Before updateBike()
00> [00:00:48.160,949] <inf> app: Before getBikeData()
00> [00:00:48.161,041] <inf> app: Before cscs notify
00> [00:00:48.161,041] <inf> app: Before cps notify
00> [00:00:48.161,071] <inf> app: Before ftms bike data notify
00> [00:00:48.161,071] <inf> app: Before ftms status notify
00> [00:00:48.161,071] <inf> app: Before updateDisplay()
00> [00:00:48.382,354] <inf> app: Before sleep
00> [00:00:48.642,456] <inf> app: After sleep
00> [00:00:48.642,486] <inf> app: Execution cycle: 89
00> [00:00:48.642,486] <inf> app: Before updateBike()
00> [00:00:48.659,973] <inf> app: Before getBikeData()
00> [00:00:48.660,064] <inf> app: Before cscs notify
00> [00:00:48.660,064] <inf> app: Before cps notify
00> [00:00:48.660,095] <inf> app: Before ftms bike data notify
00> [00:00:48.660,095] <inf> app: Before ftms status notify
00> [00:00:48.660,125] <inf> app: Before updateDisplay()
00> [00:00:48.877,838] <inf> app: Before sleep
00> [00:00:49.142,944] <inf> app: After sleep
00> [00:00:49.142,944] <inf> app: Execution cycle: 90
00> [00:00:49.142,974] <inf> app: Before updateBike()
00> [00:00:49.160,278] <inf> app: Before getBikeData()
00> [00:00:49.160,369] <inf> app: Before cscs notify
00> [00:00:49.160,369] <inf> app: Before cps notify
00> [00:00:49.160,400] <inf> app: Before ftms bike data notify
00> [00:00:49.160,400] <inf> app: Before ftms status notify
00> [00:00:49.160,430] <inf> app: Before updateDisplay()
00> [00:00:49.380,493] <inf> app: Before sleep
00> [00:00:49.642,639] <inf> app: After sleep
00> [00:00:49.642,639] <inf> app: Execution cycle: 91
00> [00:00:49.642,669] <inf> app: Before updateBike()
00> [00:00:49.659,851] <inf> app: Before getBikeData()
00> [00:00:49.659,942] <inf> app: Before cscs notify
00> [00:00:49.659,942] <inf> app: Before cps notify
00> [00:00:49.659,942] <inf> app: Before ftms bike data notify
00> [00:00:49.659,973] <inf> app: Before ftms status notify
00> [00:00:49.659,973] <inf> app: Before updateDisplay()
00> [00:00:49.878,692] <inf> app: Before sleep
00> [00:00:50.142,791] <inf> app: After sleep
00> [00:00:50.142,822] <inf> app: Execution cycle: 92
00> [00:00:50.142,822] <inf> app: Before updateBike()
00> [00:00:50.160,583] <inf> app: Before getBikeData()
00> [00:00:50.160,675] <inf> app: Before cscs notify
00> [00:00:50.160,675] <inf> app: Before cps notify
00> [00:00:50.160,705] <inf> app: Before ftms bike data notify
00> [00:00:50.160,705] <inf> app: Before ftms status notify
00> [00:00:50.160,705] <inf> app: Before updateDisplay()
00> [00:00:50.380,828] <inf> app: Before sleep
00> [00:00:50.642,944] <inf> app: After sleep
00> [00:00:50.642,974] <inf> app: Execution cycle: 93
00> [00:00:50.642,974] <inf> app: Before updateBike()
(Connection lost)
  • 3348.genuine-failure.pcapng
  • 8228.badConnect-fresh-with-console-2.pcapng

Questions:

  1. For every master 'Empty PDU' - There should be a slave response, right? Mine often does not respond.
  2. Several requests seem to take very long, although still actually go out (ex - LL_FEATURE_RSP) - What could cause such a delay?  Is there a queue length I can watch?
  3. Could this be a priority issue of the BLE stack?  My app is very resource intensive (particularly LVGL / display libraries) and the calls to update the LCD screen can take 300 ms. I wonder if this is allowing the BLE stack to 'fall behind' and maybe build some queue of messages? It's not clear how Zephyr prioritizes the app code with the BLE stack.
  4. Could this be a signal/noise issue and possibly my device just isn't receiving those messages?

Info:

  • nRF Connect 2.3.0 w/ Zephyr v3.2.99-ncs2
  • Custom nRF52840 board using Raytac module w/ integrated antenna
  • Signal strength between devices is usually ~70 dBm
  • Master device is Android 12 tablet, app tested with is Zwift
  • My app implements 3 different GATT profiles (CPS, CSCS, FTMS) - Connectivity issues seem to be only with FTMS when the 0x2AD9 write-characteristic (Control Point) is used. Could just be the Zwift app uses different timeout values for those services, need to check.
Parents
  • 0

    Hi, 

    The master sends an empty PDU to maintain the Bluetooth connection when the application has no data to send. The slave would do the same time, but it doesn't have to respond to each one from the master. 

    As for your sniffer logs, we see there is something very strange with this Android 12 tablet. 

    There are a lot of missing packets in the sniffer trace. The event counter goes from 0 to 80, then 80 to 95. So the sniffer is not picking up these packets. Either the master is not sending these packets at all, or it's sending them at totally the wrong time or frequency/channel. Could you test with a different tablet/phone?

    Regards,
    Amanda H.

  • 0 in reply to Amanda Hsieh

    So I've done a lot more testing and had a breakthrough, but I'd like to make sure I'm understanding things correctly.

    I've found the initial failures with the Android 12 tablet (Lenovo P11 Plus) and the Android 14 phone (Pixel 7a) to be different, but what they have in common is once the connection fails the devices never connect again unless they're power cycled (or at least Zwift App terminated on the Android device). This issue is somehow related to the D-H Key pairing process, and removing Encryption support for my control-point characteristic eliminated the issue on the Android 14 phone entirely, and greatly improved reliability on the Android 12 device. My suspicion is the Zwift app does not handle pairing failures gracefully and continues to try and use a stale key instead of re-authenticating, restarting the App or nRF device forces the pairing process to re-occur.

    For the initial failures on the Android 12 tablet, it's hard for me to believe this is a device-specific issue because it's been observed on many other devices (although not confirmed to be exactly the same with a BLE capture). A few points about this issue/setup:

    • I only see a jump in the event counter when there are large gaps in time and a response is pending on my device. In your example - LL_FEATURE_RSP takes 3.9s to respond. I wonder if the Bluetooth stack is hanging until it sees that empty PDU?
    • You can see the same behavior in 'badConnect-fresh-with-console.pcapng' packet 5231 at 36.268s
    • Also in 'badConnect-fresh-with-console.pcapng' - It times out at 47.347s and we start broadcasting again - but we never receive the CONNECT_IND_TERMINATE
    • RSSI is -48 dBm master->slave and -60 dBm slave->master - Doesn't seem bad enough to explain ~5s gaps in communication


    For the Android 14 phone, the only way to create the issue was to fail to acknowledge the "Pairing request" on the Android device in a timely manner (more than 20 seconds). From what I can tell this is triggered by the public key exchange and once the "Pairing request" is acknowledged the DHKey check is completed. It seems when this fails it leaves both devices in a bad state and the Android application (Zwift) must be terminated (not closed) and/or the nRF52 device power-cycled.

    Here are some lines from connectedOK-android-14-2.pcapng that show the DH Key exchange:

    4712 27.666047 Slave_0xe5b21470 Master_0xe5b21470 ATT 35 0x11 256 False 0 -58 dBm Rcvd Error Response - Insufficient Encryption, Handle: 0x0027 (Unknown)
4713 27.695817 Master_0xe5b21470 Slave_0xe5b21470 SMP 37 0x13 257 False 1 -20 dBm Sent Pairing Request: AuthReq: Bonding, MITM, SecureConnection, Reserved |
4724 27.786809 Master_0xe5b21470 Slave_0xe5b21470 SMP 41 0x13 260 False 0 -20 dBm Sent Pairing Public Key
4731 27.817003 Slave_0xe5b21470 Master_0xe5b21470 SMP 41 0x11 261 True 1 -57 dBm Rcvd Pairing Public Key
4733 27.817451 Slave_0xe5b21470 Master_0xe5b21470 SMP 47 0x11 261 False 0 -57 dBm Rcvd Pairing Confirm
4734 27.845817 Master_0xe5b21470 Slave_0xe5b21470 SMP 47 0x13 262 False 1 -20 dBm Sent Pairing Random
4737 27.876012 Slave_0xe5b21470 Master_0xe5b21470 SMP 47 0x11 263 False 0 -62 dBm Rcvd Pairing Random
...Then once I accept from Android side...
5028 31.715844 Master_0xe5b21470 Slave_0xe5b21470 SMP 47 0x13 391 False 0 -21 dBm Sent Pairing DHKey Check
5030 31.745844 Master_0xe5b21470 Slave_0xe5b21470 SMP 47 0x13 392 False 0 -20 dBm Sent Pairing DHKey Check <-- Repeat?
5033 31.746511 Slave_0xe5b21470 Master_0xe5b21470 SMP 47 0x11 392 False 1 -54 dBm Rcvd Pairing DHKey Check

    If the latter does not happen, the connection terminates unexpectedly after ~30 seconds. I do not know where that timeout is defined, but the initial connection then failure is quite confusing to troubleshoot. I think because I allowed both encrypted and non-encrypted writes it initially connected non-encrypted and then when encryption failed disconnected.

    To summarize - Removing the BT_GATT_PERM_WRITE_ENCRYPT advertisement from my control point characteristic fixed almost everything, but it's not clear to me why it was so unreliable and inconsistent. Also I suspect there are still connectivity issues with the Android 12 tablet, but at least now it can re-connect on failure, when before devices had to be power cycled.

    connectedOK-android-14-2.pcapng

  • 0 in reply to nategreco
    nategreco said:
    I wonder if the Bluetooth stack is hanging until it sees that empty PDU?

    The Bluetooth stack is processing, but there is no data to send, so it sends an empty PDU. You can enable the debug log to check it. 

    nategreco said:
    It times out at 47.347s and we start broadcasting again - but we never receive the CONNECT_IND_TERMINATE

    It seems the device reset suddenly, and needs to check the debug log from the device.

    nategreco said:
    From what I can tell this is triggered by the public key exchange and once the "Pairing request" is acknowledged the DHKey check is completed. It seems when this fails it leaves both devices in a bad state and the Android application (Zwift) must be terminated (not closed) and/or the nRF52 device power-cycled.
    nategreco said:
    If the latter does not happen, the connection terminates unexpectedly after ~30 seconds. I do not know where that timeout is defined, but the initial connection then failure is quite confusing to troubleshoot.

    Could you test with the nRF Connet app and provide the sniffer log? Do you see the same behavior? 

    -Amanda H.

Reply
  • 0 in reply to nategreco
    nategreco said:
    I wonder if the Bluetooth stack is hanging until it sees that empty PDU?

    The Bluetooth stack is processing, but there is no data to send, so it sends an empty PDU. You can enable the debug log to check it. 

    nategreco said:
    It times out at 47.347s and we start broadcasting again - but we never receive the CONNECT_IND_TERMINATE

    It seems the device reset suddenly, and needs to check the debug log from the device.

    nategreco said:
    From what I can tell this is triggered by the public key exchange and once the "Pairing request" is acknowledged the DHKey check is completed. It seems when this fails it leaves both devices in a bad state and the Android application (Zwift) must be terminated (not closed) and/or the nRF52 device power-cycled.
    nategreco said:
    If the latter does not happen, the connection terminates unexpectedly after ~30 seconds. I do not know where that timeout is defined, but the initial connection then failure is quite confusing to troubleshoot.

    Could you test with the nRF Connet app and provide the sniffer log? Do you see the same behavior? 

    -Amanda H.

Children
No Data
Related
Terms of service