zephyr: Bluetooth: Controller: Syncing with devices with per. adv. int. < ~10ms eventually causes events from BT controller stop arriving

Describe the bug When using periodic adv. intervals <~10ms then sometimes BT Controller stops reporting any events, including sync termination, CTEs, scan events etc.

• What target platform are you using? nRF52833, Zephyr
• Is this a regression? Not checked.

To Reproduce Have 10 tags sending per. adv. with 7.5ms interval with adv. train of 5 and CTE enabled. I have not found replicatable way to reproduce, sometimes it’s enough to just let all 10 tags sync and then wait a minute and it happens. Sometimes it’s easier to reproduce by randomly resetting some tags. I have reproduced without CTE sampling enabled, however may or may not be easier to reproduce with it on. I have also reproduced with only 5-6 tags but I think it’s easier with more.

Application: aoa_receiver_multiple_49915.zip

Expected behavior BT controller keeps reporting events.

Impact BT Controller stops generating events, application will be in strange state.

Logs and console output The application prints <wrn> main: Interval: 6 whenever a device sending per. adv. is seen, as can be seen it’s stopped reporting at the end.

*** Booting Zephyr OS build zephyr-v3.1.0-4244-g1995d349db37  ***
Starting Connectionless Locator Demo
Bluetooth initialization...success
Scan callbacks register...success.
Periodic Advertising callbacks register...success.
Start scanning...success
[00:00:00.004,638] <inf> main: Creating Sync for tags in list
Waiting for periodic advertising...
Scan is running...
[00:00:00.328,277] <wrn> main: Interval: 6
[00:00:00.328,521] <dbg> main: scan_recv: Added tag from per adv list
[00:00:00.470,764] <wrn> main: Interval: 6
[00:00:00.470,977] <dbg> main: scan_recv: Added tag from per adv list
[00:00:00.498,992] <wrn> main: Interval: 6
[00:00:00.499,206] <dbg> main: scan_recv: Added tag from per adv list
Scan is running...
[00:00:00.709,167] <wrn> main: Interval: 6
(709) PER_ADV_SYNC[0]: [DEVICE]: 36:DC:42:90:4D:0E (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:00.710,174] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:00.710,174] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(710) success. CTE receive enabled.
[00:00:00.741,027] <wrn> main: Interval: 6
[00:00:00.741,241] <dbg> main: scan_recv: Added tag from per adv list
[00:00:00.762,207] <wrn> main: Interval: 6
[00:00:00.762,420] <dbg> main: scan_recv: Added tag from per adv list
[00:00:00.883,422] <wrn> main: Interval: 6
[00:00:00.883,666] <dbg> main: scan_recv: Added tag from per adv list
[00:00:00.972,381] <wrn> main: Interval: 6
(988) PER_ADV_SYNC[1]: [DEVICE]: 3B:66:BD:7F:64:67 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:00.988,983] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:00.989,013] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(989) success. CTE receive enabled.
Running...
TAGS:sync...,sync...,33,sync...,2,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 4 Synced: 2 Num err: 0/35
[00:00:01.096,862] <wrn> main: Interval: 6
[00:00:01.097,106] <dbg> main: scan_recv: Added tag from per adv list
Scan is running...
[00:00:01.310,974] <wrn> main: Interval: 6
(1312) PER_ADV_SYNC[2]: [DEVICE]: 08:F7:34:24:2B:28 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:01.312,622] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:01.312,622] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(1313) success. CTE receive enabled.
[00:00:01.730,895] <wrn> main: Interval: 6
Scan is running...
[00:00:01.944,915] <wrn> main: Interval: 6
[00:00:01.945,129] <dbg> main: scan_recv: Added tag from per adv list
Running...
TAGS:sync...,55,56,sync...,66,sync...,sync...,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 5 Synced: 3 Num err: 0/178
[00:00:02.179,016] <wrn> main: Interval: 6
[00:00:02.442,382] <wrn> main: Interval: 6
Scan is running...
[00:00:02.598,999] <wrn> main: Interval: 6
[00:00:02.862,396] <wrn> main: Interval: 6
Running...
TAGS:sync...,79,49,sync...,59,sync...,sync...,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 5 Synced: 3 Num err: 0/191
[00:00:03.018,981] <wrn> main: Interval: 6
[00:00:03.035,156] <wrn> main: Interval: 6
[00:00:03.035,369] <dbg> main: scan_recv: Added tag from per adv list
[00:00:03.197,052] <wrn> main: Interval: 6
(3197) PER_ADV_SYNC[3]: [DEVICE]: 28:B5:CF:0A:86:88 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:03.198,150] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:03.198,181] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(3198) success. CTE receive enabled.
[00:00:03.268,554] <wrn> main: Interval: 6
(3276) PER_ADV_SYNC[4]: [DEVICE]: 1D:29:0E:6A:E8:65 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:03.277,221] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:03.277,221] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(3277) success. CTE receive enabled.
Scan is running...
[00:00:03.613,586] <wrn> main: Interval: 6
(3621) PER_ADV_SYNC[5]: [DEVICE]: 17:50:92:34:97:F7 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:03.622,253] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:03.622,253] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(3622) success. CTE receive enabled.
[00:00:03.912,384] <wrn> main: Interval: 6
Running...
TAGS:19,82,44,sync...,53,13,144,sync...,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 3 Synced: 6 Num err: 0/358
[00:00:04.050,933] <wrn> main: Interval: 40
[00:00:04.069,000] <wrn> main: Interval: 6
[00:00:04.453,491] <wrn> main: Interval: 6
[00:00:04.671,020] <wrn> main: Interval: 6
[00:00:04.948,516] <wrn> main: Interval: 6
Running...
TAGS:24,64,21,sync...,35,30,204,sync...,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 3 Synced: 6 Num err: 0/384
Scan is running...
[00:00:05.368,530] <wrn> main: Interval: 6
Running...
TAGS:24,56,30,sync...,32,35,196,sync...,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 3 Synced: 6 Num err: 0/381
[00:00:06.150,970] <wrn> main: Interval: 40
[00:00:06.185,180] <wrn> main: Interval: 6
(6207) PER_ADV_SYNC[6]: [DEVICE]: 2B:D6:79:55:8E:32 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:06.207,916] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:06.207,916] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(6208) success. CTE receive enabled.
[00:00:06.418,548] <wrn> main: Interval: 6
[00:00:06.770,996] <wrn> main: Interval: 6
Scan is running...
Running...
TAGS:27,37,23,sync...,27,35,191,sync...,16,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 2 Synced: 7 Num err: 0/367
[00:00:07.191,009] <wrn> main: Interval: 6
[00:00:07.200,988] <wrn> main: Interval: 40
[00:00:07.654,937] <wrn> main: Interval: 6
[00:00:07.888,549] <wrn> main: Interval: 6
Running...
TAGS:27,43,36,sync...,37,44,170,sync...,20,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 2 Synced: 7 Num err: 0/380
[00:00:08.034,912] <wrn> main: Interval: 6
(8088) PER_ADV_SYNC[7]: [DEVICE]: 17:BB:4D:10:4D:39 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:08.089,447] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:08.089,447] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(8090) success. CTE receive enabled.
Scan is running...
[00:00:08.867,034] <wrn> main: Interval: 6
Running...
TAGS:40,55,21,sync...,25,32,17,14,18,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 1 Synced: 8 Num err: 0/223
[00:00:09.287,017] <wrn> main: Interval: 6
[00:00:09.560,943] <wrn> main: Interval: 6
(9570) PER_ADV_SYNC[8]: [DEVICE]: 3A:9E:4A:1C:6F:D1 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:09.570,434] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:09.570,465] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(9570) success. CTE receive enabled.
Scan is running...
[00:00:09.710,906] <wrn> main: Interval: 6
[00:00:09.783,935] <err> bt_scan: Prepare CTE conn IQ report failed -22
Running...
TAGS:33,53,30,15,31,38,18,21,21,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/263
[00:00:10.134,857] <wrn> main: Interval: 6
Running...
TAGS:37,50,27,44,31,34,21,23,21,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/289
[00:00:11.030,792] <wrn> main: Interval: 6
[00:00:11.038,604] <wrn> main: Interval: 6
Scan is running...
[00:00:12.008,056] <err> bt_scan: Prepare CTE conn IQ report failed -22
Running...
TAGS:39,49,22,43,34,40,11,18,17,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/281
[00:00:12.049,133] <wrn> main: Interval: 6
[00:00:12.436,981] <wrn> main: Interval: 6
[00:00:12.445,037] <wrn> main: Interval: 6
Running...
TAGS:39,55,24,39,24,28,16,16,19,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/262
[00:00:13.740,722] <err> bt_scan: Prepare CTE conn IQ report failed -22
Running...
TAGS:30,44,27,39,32,34,19,19,20,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/277
[00:00:14.116,912] <wrn> main: Interval: 6
Scan is running...
Running...
TAGS:23,49,26,24,32,31,14,18,17,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/244
[00:00:15.251,892] <wrn> main: Interval: 6
[00:00:15.586,822] <wrn> main: Interval: 6
[00:00:16.003,265] <wrn> main: Interval: 6
Running...
TAGS:28,46,23,29,32,33,18,19,20,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 9 Num err: 0/260
[00:00:16.054,779] <wrn> main: Interval: 6
[00:00:16.424,407] <wrn> main: Interval: 6
[00:00:16.424,652] <dbg> main: scan_recv: Added tag from per adv list
[00:00:16.435,058] <wrn> main: Interval: 6
Scan is running...
Running...
TAGS:23,52,20,39,28,34,12,13,14,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 1 Synced: 9 Num err: 0/235
[00:00:17.270,812] <wrn> main: Interval: 6
[00:00:17.900,756] <wrn> main: Interval: 6
Running...
TAGS:25,64,23,41,31,36,14,20,21,sync...,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 1 Synced: 9 Num err: 0/280
[00:00:18.734,436] <wrn> main: Interval: 6
(18773) PER_ADV_SYNC[9]: [DEVICE]: 2B:DA:D3:2E:AE:89 (random) synced, Interval 0x0006 (7 ms), PHY LE 2M
[00:00:18.774,322] <dbg> main: sync_cb: Removed tag from per adv list
[00:00:18.774,353] <inf> main: Creating Sync for tags in list
Enable receiving of CTE...
(18775) success. CTE receive enabled.
[00:00:18.961,120] <wrn> main: Interval: 40
Running...
TAGS:23,45,27,31,26,31,14,14,17,2,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/237
Running...
----->After here no events arrive from controller, even powering of tags etc. won't generate sync term<-----
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0
Running...
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0
Running...
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0
Running...
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0
Running...
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0
Running...
TAGS:0,0,0,0,0,0,0,0,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 0 Synced: 10 Num err: 0/0

Environment (please complete the following information):

• OS: Windows
• Toolchain: Zephyr
• Commit SHA or Version used: 894423e9aed34a394b97c995c33549513b0ac4a5