search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.55k stars 6.46k forks source link

Bluetooth: Peripheral disconnected with BT_HCI_ERR_LL_RESP_TIMEOUT reason and SMP timeout #53334

Closed ahmedmoheb-nordic closed 1 year ago

ahmedmoheb-nordic commented 1 year ago

Application flow

  1. There are 4 advertising peripherals which the central connects to them one after another
  2. After establishing the connection and the connected callback is received, bt_conn_set_security() is scheduled to set the connection security level to BT_SECURITY_L2 though a delayed work queue item
  3. MTU is exchanged between the central and connected peripherals

Describe the bug

To Reproduce Steps to reproduce the behavior:

  1. Checkout this commit 7284fff6e0735564c89460c0c6183283ff20c3ac
  2. Run ~/zephyrproject/zephyr/tests/bluetooth/bsim_bt/bsim_test_conn_stress/tests_scripts/conn_stress.sh

Logs and console output

d_04: @00:00:00.000000  *** Booting Zephyr OS build zephyr-v3.2.0-2825-g3a53a010f3ec ***
d_01: @00:00:00.000000  *** Booting Zephyr OS build zephyr-v3.2.0-2825-g3a53a010f3ec ***
d_02: @00:00:00.000000  *** Booting Zephyr OS build zephyr-v3.2.0-2825-g3a53a010f3ec ***
d_00: @00:00:00.000000  *** Booting Zephyr OS build zephyr-v3.2.0-2901-g630df1aaddbc ***
d_03: @00:00:00.000000  *** Booting Zephyr OS build zephyr-v3.2.0-2825-g3a53a010f3ec ***
d_04: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
d_04: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
d_04: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
d_00: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
d_00: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
d_02: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
d_00: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
d_02: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
d_02: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
d_04: @00:00:00.000000  [00:00:00.000,000] <wrn> bt_id: bt_read_static_addr: No static addresses stored in controller
d_03: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
d_03: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
d_03: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
d_01: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
d_01: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
d_04: @00:00:00.000000  [Peripheral] : Initializing Test
d_01: @00:00:00.000000  [00:00:00.000,000] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
d_00: @00:00:00.000000  [00:00:00.000,000] <wrn> bt_id: bt_read_static_addr: No static addresses stored in controller
d_02: @00:00:00.000000  [00:00:00.000,000] <wrn> bt_id: bt_read_static_addr: No static addresses stored in controller
d_00: @00:00:00.000000  [Central] : Initializing Test
d_01: @00:00:00.000000  [00:00:00.000,000] <wrn> bt_id: bt_read_static_addr: No static addresses stored in controller
d_02: @00:00:00.000000  [Peripheral] : Initializing Test
d_03: @00:00:00.000000  [00:00:00.000,000] <wrn> bt_id: bt_read_static_addr: No static addresses stored in controller
d_01: @00:00:00.000000  [Peripheral] : Initializing Test
d_03: @00:00:00.000000  [Peripheral] : Initializing Test
d_02: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: Identity: DD:D1:7D:F0:5F:33 (random)
d_02: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
d_02: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
d_02: @00:00:00.004568  [Peripheral] : Bluetooth initialized
d_00: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: Identity: DE:CD:A2:21:EE:22 (random)
d_00: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
d_00: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
d_00: @00:00:00.004568  [Central] : Bluetooth initialized
d_01: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: Identity: CB:04:A6:15:1F:50 (random)
d_01: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
d_01: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
d_01: @00:00:00.004568  [Peripheral] : Bluetooth initialized
d_00: @00:00:00.004938  [Central] : Scanning successfully started
d_01: @00:00:00.004938  [Peripheral] : Advertising successfully started
d_02: @00:00:00.004938  [Peripheral] : Advertising successfully started
d_03: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: Identity: F4:7E:23:D3:37:EA (random)
d_03: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
d_03: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
d_03: @00:00:00.004568  [Peripheral] : Bluetooth initialized
d_04: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: Identity: DD:FA:EA:DB:58:6A (random)
d_04: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
d_04: @00:00:00.004568  [00:00:00.004,547] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
d_04: @00:00:00.004568  [Peripheral] : Bluetooth initialized
d_04: @00:00:00.004938  [Peripheral] : Advertising successfully started
d_03: @00:00:00.004938  [Peripheral] : Advertising successfully started
d_00: @00:00:00.007160  [Central] : ------------------------------------------------------
d_00: @00:00:00.007160  [Central] : [DEVICE]: 7A:7C:28:1F:71:40 (random), AD evt type 0, AD data len 3, RSSI -35
d_00: @00:00:00.007160  [Central] : ------------------------------------------------------
d_00: @00:00:00.007916  [Central] : ------------------------------------------------------
d_00: @00:00:00.007916  [Central] : [DEVICE]: 7A:7C:28:1F:71:40 (random), AD evt type 4, AD data len 19, RSSI -35
d_00: @00:00:00.007916  [Central] : ------------------------------------------------------
d_00: @00:00:00.007916  [Central] : Device name : Zephyr Peripheral
d_00: @00:00:00.007917  [Central] : Scanning successfully stopped
d_00: @00:00:00.007917  [Central] : Connecting to 7A:7C:28:1F:71:40 (random)
d_01: @00:00:00.114719  [Peripheral] : Updated MTU: TX: 23 RX: 23 bytes
d_01: @00:00:00.114719  [Peripheral] : Connection 0x80d3060 established : 60:5D:FC:C7:1A:F4 (random)
d_00: @00:00:00.114716  [Central] : Updated MTU: TX: 23 RX: 23 bytes
d_00: @00:00:00.114716  [Central] : Connection 0x80d35c0 established : 7A:7C:28:1F:71:40 (random)
d_00: @00:00:00.114716  [Central] : Active connections count : 1
d_00: @00:00:00.114716  [Central] : Peer address 7A:7C:28:1F:71:40 (random) not found, returning index 0
d_00: @00:00:00.114716  [Central] : Connection reference store index 0
d_00: @00:00:00.114716  [Central] : * ********************************************** *
d_00: @00:00:00.114716  [Central] : * Scheduling setting security level delayed work *
d_00: @00:00:00.114716  [Central] : * ********************************************** *
d_00: @00:00:00.369233  [Central] : * ****************** *
d_00: @00:00:00.369233  [Central] : * Elapsed time : 260 *
d_00: @00:00:00.369233  [Central] : * ****************** *
d_00: @00:00:00.369233  [Central] : Setting security level for connection 0x80d35c0 with peer 7A:7C:28:1F:71:40 (random) is set to : 2
d_00: @00:00:00.370441  [Central] : Security level for connection 0x80d35c0 with peer 7A:7C:28:1F:71:40 (random) is set to : 2
d_01: @00:00:00.966046  [Peripheral] : Security for 0x80d3060 changed: 60:5D:FC:C7:1A:F4 (random) level 2
d_01: @00:00:00.977967  [Peripheral] : Discovering peer 60:5D:FC:C7:1A:F4 (random) primary service
d_00: @00:00:01.016241  [Central] : Security for conn (0) @ 0x80d35c0 changed: 7A:7C:28:1F:71:40 (random) level 2
d_00: @00:00:01.017904  [Central] : Scanning successfully started
d_00: @00:00:01.017904  [Central] : Updating MTU for CB:04:A6:15:1F:50 (random)...
d_00: @00:00:01.068725  [Central] : ------------------------------------------------------
d_00: @00:00:01.068725  [Central] : [DEVICE]: 5A:FC:A8:11:BA:57 (random), AD evt type 0, AD data len 3, RSSI -35
d_00: @00:00:01.068725  [Central] : ------------------------------------------------------
d_00: @00:00:01.069481  [Central] : ------------------------------------------------------
d_00: @00:00:01.069481  [Central] : [DEVICE]: 5A:FC:A8:11:BA:57 (random), AD evt type 4, AD data len 19, RSSI -35
d_00: @00:00:01.069481  [Central] : ------------------------------------------------------
d_00: @00:00:01.069481  [Central] : Device name : Zephyr Peripheral
d_00: @00:00:01.069482  [Central] : Scanning successfully stopped
d_00: @00:00:01.069482  [Central] : Connecting to 5A:FC:A8:11:BA:57 (random)
d_01: @00:00:01.166079  [Peripheral] : Primary Service Found
d_01: @00:00:01.166511  [Peripheral] : Updated MTU: TX: 247 RX: 247 bytes
d_01: @00:00:01.166511  [Peripheral] : Updating MTU succeeded DE:CD:A2:21:EE:22 (random)
d_03: @00:00:01.172763  [Peripheral] : Updated MTU: TX: 23 RX: 23 bytes
d_03: @00:00:01.172763  [Peripheral] : Connection 0x80d3060 established : 60:5D:FC:C7:1A:F4 (random)
d_00: @00:00:01.172770  [Central] : Updated MTU: TX: 23 RX: 23 bytes
d_00: @00:00:01.172770  [Central] : Connection 0x80d3678 established : 5A:FC:A8:11:BA:57 (random)
d_00: @00:00:01.172770  [Central] : Active connections count : 2
d_00: @00:00:01.172770  [Central] : Peer address 5A:FC:A8:11:BA:57 (random) not found, returning index 1
d_00: @00:00:01.172770  [Central] : Connection reference store index 1
d_00: @00:00:01.172770  [Central] : * ********************************************** *
d_00: @00:00:01.172770  [Central] : * Scheduling setting security level delayed work *
d_00: @00:00:01.172770  [Central] : * ********************************************** *
d_01: @00:00:01.216149  [Peripheral] : Service Characteristic Found
d_00: @00:00:01.216387  [Central] : Updated MTU: TX: 247 RX: 247 bytes
d_00: @00:00:01.216387  [Central] : MTU exchange addr CB:04:A6:15:1F:50 (random) conn 0 successful
d_00: @00:00:01.217469  [Central] : Discovering peer CB:04:A6:15:1F:50 (random) primary service
d_01: @00:00:01.316081  [Peripheral] : [SUBSCRIBED] addr DE:CD:A2:21:EE:22 (random)
d_00: @00:00:01.316327  [Central] : Primary Service Found
d_00: @00:00:01.416381  [Central] : Service Characteristic Found
d_00: @00:00:01.427033  [Central] : * ****************** *
d_00: @00:00:01.427033  [Central] : * Elapsed time : 260 *
d_00: @00:00:01.427033  [Central] : * ****************** *
d_00: @00:00:01.427033  [Central] : Setting security level for connection 0x80d3678 with peer 5A:FC:A8:11:BA:57 (random) is set to : 2
d_00: @00:00:01.428241  [Central] : Security level for connection 0x80d3678 with peer 5A:FC:A8:11:BA:57 (random) is set to : 2
d_00: @00:00:01.516277  [Central] : Setting connection store index 0 peer address CB:04:A6:15:1F:50 (random)
d_00: @00:00:01.516277  [Central] : [SUBSCRIBED] addr CB:04:A6:15:1F:50 (random) conn 0
d_03: @00:00:01.967212  [Peripheral] : Security for 0x80d3060 changed: 60:5D:FC:C7:1A:F4 (random) level 2
d_03: @00:00:01.975892  [Peripheral] : Discovering peer 60:5D:FC:C7:1A:F4 (random) primary service
d_00: @00:00:02.017406  [Central] : Security for conn (1) @ 0x80d3678 changed: 5A:FC:A8:11:BA:57 (random) level 2
d_00: @00:00:02.035787  [Central] : Scanning successfully started
d_00: @00:00:02.035787  [Central] : Updating MTU for F4:7E:23:D3:37:EA (random)...
d_03: @00:00:02.117243  [Peripheral] : Primary Service Found
d_03: @00:00:02.117675  [Peripheral] : Updated MTU: TX: 247 RX: 247 bytes
d_03: @00:00:02.117675  [Peripheral] : Updating MTU succeeded DE:CD:A2:21:EE:22 (random)
d_03: @00:00:02.167315  [Peripheral] : Service Characteristic Found
d_00: @00:00:02.167554  [Central] : Updated MTU: TX: 247 RX: 247 bytes
d_00: @00:00:02.167554  [Central] : MTU exchange addr F4:7E:23:D3:37:EA (random) conn 1 successful
d_00: @00:00:02.175477  [Central] : Discovering peer F4:7E:23:D3:37:EA (random) primary service
d_00: @00:00:02.328378  [Central] : ------------------------------------------------------
d_00: @00:00:02.328378  [Central] : [DEVICE]: 68:11:15:89:AB:56 (random), AD evt type 0, AD data len 3, RSSI -35
d_00: @00:00:02.328378  [Central] : ------------------------------------------------------
d_00: @00:00:02.329134  [Central] : ------------------------------------------------------
d_00: @00:00:02.329134  [Central] : [DEVICE]: 68:11:15:89:AB:56 (random), AD evt type 4, AD data len 19, RSSI -35
d_00: @00:00:02.329134  [Central] : ------------------------------------------------------
d_00: @00:00:02.329134  [Central] : Device name : Zephyr Peripheral
d_00: @00:00:02.329135  [Central] : Scanning successfully stopped
d_00: @00:00:02.329135  [Central] : Connecting to 68:11:15:89:AB:56 (random)
d_03: @00:00:02.417247  [Peripheral] : [SUBSCRIBED] addr DE:CD:A2:21:EE:22 (random)
d_00: @00:00:02.417493  [Central] : Primary Service Found
d_02: @00:00:02.437900  [Peripheral] : Updated MTU: TX: 23 RX: 23 bytes
d_02: @00:00:02.437900  [Peripheral] : Connection 0x80d3060 established : 60:5D:FC:C7:1A:F4 (random)
d_00: @00:00:02.437917  [Central] : Updated MTU: TX: 23 RX: 23 bytes
d_00: @00:00:02.437917  [Central] : Connection 0x80d3730 established : 68:11:15:89:AB:56 (random)
d_00: @00:00:02.437917  [Central] : Active connections count : 3
d_00: @00:00:02.437917  [Central] : Peer address 68:11:15:89:AB:56 (random) not found, returning index 2
d_00: @00:00:02.437917  [Central] : Connection reference store index 2
d_00: @00:00:02.437917  [Central] : * ********************************************** *
d_00: @00:00:02.437917  [Central] : * Scheduling setting security level delayed work *
d_00: @00:00:02.437917  [Central] : * ********************************************** *
d_00: @00:00:02.517546  [Central] : Service Characteristic Found
d_00: @00:00:02.694397  [Central] : * ****************** *
d_00: @00:00:02.694397  [Central] : * Elapsed time : 260 *
d_00: @00:00:02.694397  [Central] : * ****************** *
d_00: @00:00:02.694397  [Central] : Setting security level for connection 0x80d3730 with peer 68:11:15:89:AB:56 (random) is set to : 2
d_00: @00:00:02.695605  [Central] : Security level for connection 0x80d3730 with peer 68:11:15:89:AB:56 (random) is set to : 2
d_00: @00:00:06.616822  [Central] : Setting connection store index 1 peer address F4:7E:23:D3:37:EA (random)
d_00: @00:00:06.616822  [Central] : [SUBSCRIBED] addr F4:7E:23:D3:37:EA (random) conn 1
d_00: @00:00:06.616822  [Central] : LE conn param req: F4:7E:23:D3:37:EA (random) int (0x0018 (~30 ms), 0x0028 (~50 ms)) lat 0 to 42
d_00: @00:00:06.616822  [Central] : Updating F4:7E:23:D3:37:EA (random)... connection parameters
d_00: @00:00:06.616822  [Central] : Updating connection parameters succeeded F4:7E:23:D3:37:EA (random)
d_00: @00:00:06.616822  [Central] disconnected:504 : Connection (0) @ 0x80d35c0 with Peer CB:04:A6:15:1F:50 (random) terminated (reason 0x08)
d_00: @00:00:06.616822  [00:00:06.616,821] <wrn> bt_att: att_get: Not connected
d_00: @00:00:06.616822  [Central] notify_peer:871 : Couldn't send GATT notification conn 0x80d35c0
d_03: @00:00:07.017763  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:0 length 220 cnt 0
d_03: @00:00:07.067219  [Peripheral] : LE conn param updated: DE:CD:A2:21:EE:22 (random) int 0x0028 (~50 ms) lat 0 to 400
d_03: @00:00:07.067719  [Peripheral] : LE conn param req: DE:CD:A2:21:EE:22 (random) int (0x000a (~12 ms), 0x0020 (~40 ms)) lat 0 to 400
d_02: @00:00:07.218372  [Peripheral] : Security for 0x80d3060 changed: 60:5D:FC:C7:1A:F4 (random) level 2
d_02: @00:00:07.224976  [Peripheral] : Discovering peer 60:5D:FC:C7:1A:F4 (random) primary service
d_00: @00:00:07.268566  [Central] : Security for conn (2) @ 0x80d3730 changed: 68:11:15:89:AB:56 (random) level 2
d_00: @00:00:08.318610  [Central] : Updating MTU for DD:D1:7D:F0:5F:33 (random)...
d_01: @00:00:10.616463  [Peripheral] disconnected:88 : Connection @ 0x80d3060 with Peer DE:CD:A2:21:EE:22 (random) terminated (reason 0x08)
d_01: @00:00:10.616463  [00:00:10.616,455] <wrn> bt_att: att_get: Not connected
d_01: @00:00:10.616463  [Peripheral] notify_peer:417 : Couldn't send GATT notification conn (nil)
d_00: @00:00:12.267532  [Central] : LE conn param updated: F4:7E:23:D3:37:EA (random) int 0x0020 (~40 ms) lat 0 to 400
d_00: @00:00:12.267532  [Central] : LE conn param req: DD:D1:7D:F0:5F:33 (random) int (0x0018 (~30 ms), 0x0028 (~50 ms)) lat 0 to 42
d_00: @00:00:12.267532  [Central] : Updating DD:D1:7D:F0:5F:33 (random)... connection parameters
d_00: @00:00:12.267532  [Central] : Updating connection parameters succeeded DD:D1:7D:F0:5F:33 (random)
d_00: @00:00:12.267532  [Central] disconnected:504 : Connection (1) @ 0x80d3678 with Peer F4:7E:23:D3:37:EA (random) terminated (reason 0x08)
d_03: @00:00:12.267665  [Peripheral] disconnected:88 : Connection @ 0x80d3060 with Peer DE:CD:A2:21:EE:22 (random) terminated (reason 0x08)
d_03: @00:00:12.267665  [00:00:12.267,639] <wrn> bt_att: att_get: Not connected
d_03: @00:00:12.267665  [Peripheral] notify_peer:417 : Couldn't send GATT notification conn (nil)
d_00: @00:00:12.284475  [Central] : Scanning successfully started
d_02: @00:00:12.318403  [Peripheral] : Primary Service Found
d_02: @00:00:12.318835  [Peripheral] : Updated MTU: TX: 247 RX: 247 bytes
d_02: @00:00:12.318835  [Peripheral] : Updating MTU succeeded DE:CD:A2:21:EE:22 (random)
d_00: @00:00:12.325428  [Central] : ------------------------------------------------------
d_00: @00:00:12.325428  [Central] : [DEVICE]: 7A:4D:09:81:30:B1 (random), AD evt type 0, AD data len 3, RSSI -35
d_00: @00:00:12.325428  [Central] : ------------------------------------------------------
d_00: @00:00:12.326184  [Central] : ------------------------------------------------------
d_00: @00:00:12.326184  [Central] : [DEVICE]: 7A:4D:09:81:30:B1 (random), AD evt type 4, AD data len 19, RSSI -35
d_00: @00:00:12.326184  [Central] : ------------------------------------------------------
d_00: @00:00:12.326184  [Central] : Device name : Zephyr Peripheral
d_00: @00:00:12.326185  [Central] : Scanning successfully stopped
d_00: @00:00:12.326185  [Central] : Connecting to 7A:4D:09:81:30:B1 (random)
d_02: @00:00:12.418380  [Peripheral] : LE conn param updated: DE:CD:A2:21:EE:22 (random) int 0x0028 (~50 ms) lat 0 to 400
d_00: @00:00:12.418618  [Central] : Updated MTU: TX: 247 RX: 247 bytes
d_00: @00:00:12.418618  [Central] : MTU exchange addr DD:D1:7D:F0:5F:33 (random) conn 2 successful
d_02: @00:00:12.418924  [Peripheral] : LE conn param req: DE:CD:A2:21:EE:22 (random) int (0x000a (~12 ms), 0x0020 (~40 ms)) lat 0 to 400
d_02: @00:00:12.419436  [Peripheral] : Service Characteristic Found
d_00: @00:00:12.424164  [Central] : Discovering peer DD:D1:7D:F0:5F:33 (random) primary service
d_04: @00:00:12.426914  [Peripheral] : Updated MTU: TX: 23 RX: 23 bytes
d_04: @00:00:12.426914  [Peripheral] : Connection 0x80d3060 established : 60:5D:FC:C7:1A:F4 (random)
d_00: @00:00:12.426941  [Central] : Updated MTU: TX: 23 RX: 23 bytes
d_00: @00:00:12.426941  [Central] : Connection 0x80d35c0 established : 7A:4D:09:81:30:B1 (random)
d_00: @00:00:12.426941  [Central] : Active connections count : 2
d_00: @00:00:12.426941  [Central] : Peer address 7A:4D:09:81:30:B1 (random) not found, returning index 3
d_00: @00:00:12.426941  [Central] : Connection reference store index 3
d_00: @00:00:12.426941  [Central] : * ********************************************** *
d_00: @00:00:12.426941  [Central] : * Scheduling setting security level delayed work *
d_00: @00:00:12.426941  [Central] : * ********************************************** *
d_02: @00:00:12.518908  [Peripheral] : [SUBSCRIBED] addr DE:CD:A2:21:EE:22 (random)
d_00: @00:00:12.519927  [00:00:12.519,897] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:12.568653  [Central] : Primary Service Found
d_04: @00:00:12.619624  [00:00:12.619,598] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:12.668706  [Central] : Service Characteristic Found
d_00: @00:00:12.683625  [Central] : * ****************** *
d_00: @00:00:12.683625  [Central] : * Elapsed time : 260 *
d_00: @00:00:12.683625  [Central] : * ****************** *
d_00: @00:00:12.683625  [Central] : Setting security level for connection 0x80d35c0 with peer 7A:4D:09:81:30:B1 (random) is set to : 2
d_00: @00:00:12.684833  [Central] : Security level for connection 0x80d35c0 with peer 7A:4D:09:81:30:B1 (random) is set to : 2
d_00: @00:00:12.768602  [Central] : Setting connection store index 2 peer address DD:D1:7D:F0:5F:33 (random)
d_00: @00:00:12.768602  [Central] : [SUBSCRIBED] addr DD:D1:7D:F0:5F:33 (random) conn 2
d_02: @00:00:12.866425  [Peripheral] : LE conn param updated: DE:CD:A2:21:EE:22 (random) int 0x0020 (~40 ms) lat 0 to 400
d_00: @00:00:12.866486  [Central] : LE conn param updated: DD:D1:7D:F0:5F:33 (random) int 0x0020 (~40 ms) lat 0 to 400
d_02: @00:00:13.632531  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:0 length 220 cnt 0
d_00: @00:00:13.832689  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:0 DD:D1 length 220 cnt 0
d_02: @00:00:23.633455  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:100 length 220 cnt 100
d_00: @00:00:23.829617  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:100 DD:D1 length 220 cnt 100
d_02: @00:00:33.593455  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:200 length 220 cnt 200
d_00: @00:00:33.791154  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:200 DD:D1 length 220 cnt 200
d_00: @00:00:42.910767  [00:00:42.910,766] <err> bt_smp: smp_timeout: SMP Timeout
d_00: @00:00:42.910767  [Central] security_changed:568 : Security for 0x80d35c0 failed: 7A:4D:09:81:30:B1 (random) level 1 err 9
d_04: @00:00:42.960663  [00:00:42.960,662] <err> bt_smp: smp_timeout: SMP Timeout
d_04: @00:00:42.960663  [Peripheral] security_changed:131 : Security for 0x80d3060 failed: 60:5D:FC:C7:1A:F4 (random) level 1 err 9
d_02: @00:00:43.593455  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:300 length 220 cnt 300
d_00: @00:00:43.789618  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:300 DD:D1 length 220 cnt 300
d_00: @00:00:52.419784  [Central] disconnected:504 : Connection (3) @ 0x80d35c0 with Peer 7A:4D:09:81:30:B1 (random) terminated (reason 0x22)
d_04: @00:00:52.519590  [Peripheral] disconnected:88 : Connection @ 0x80d3060 with Peer 60:5D:FC:C7:1A:F4 (random) terminated (reason 0x22)
d_02: @00:00:53.553455  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:400 length 220 cnt 400
d_00: @00:00:53.749617  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:400 DD:D1 length 220 cnt 400
d_02: @00:01:03.553455  [Peripheral] : [NOTIFICATION] addr DE:CD:A2:21:EE:22 (random) conn 0x80d3060 data cnt:500 length 220 cnt 500
d_00: @00:01:03.749617  [Central] : [NOTIFICATION] addr DD:D1:7D:F0:5F:33 (random) conn 2 data cnt:500 DD:D1 length 220 cnt 500
d_00: @00:01:12.388571  [Central] disconnected:504 : Connection (2) @ 0x80d3730 with Peer DD:D1:7D:F0:5F:33 (random) terminated (reason 0x15)
d_02: @00:01:12.388572  [Peripheral] disconnected:88 : Connection @ 0x80d3060 with Peer DE:CD:A2:21:EE:22 (random) terminated (reason 0x16)
github-actions[bot] commented 1 year ago

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

carlescufi commented 1 year ago

cc @jori-nordic perhaps you can show @kruithofa how to run the test.

kruithofa commented 1 year ago

This issue does not exist anymore when rebasing on the main branch. Closing the issue