search

bluekitchen / btstack

Dual-mode Bluetooth stack, with small memory footprint.
http://bluekitchen-gmbh.com
Other
1.72k stars 610 forks source link

hid examples don't work on esp32 #202

Closed fluffymadness closed 5 years ago

fluffymadness commented 5 years ago

I tried to flash and execute the hid examples for the esp32. Both, the mouse and keyboard example pair for me, but the connection gets closed after a few seconds. I tried using windows 10 and my android phone. When I try to connect to the esp32 after pairing with my phone, it says connecting, stays there for a second and disconnects afterwards. Same for windows 10. It stays connected for 10~15 secs after pairing, then disconnects. I already search around a few hours and tried various things, but no solution so far. Hopefully someone can point me in the right direction. Thanks. Here is the log:

`[00:00:00.757] LOG -- main.c.251: transport: configure SCO over HCI, result 0x0000 [00:00:00.758] LOG -- hci.c.4063: BTSTACK_EVENT_STATE 1 BTstack: execute run loop [00:00:00.762] LOG -- hci.c.1975: Manufacturer: 0x0060 [00:00:00.767] LOG -- hci.c.1889: local name: [00:00:00.770] LOG -- hci.c.1648: Received local name, need baud change 0 [00:00:00.777] LOG -- hci.c.1986: Local supported commands summary 0x3f [00:00:00.784] LOG -- hci.c.1937: Local Address, Status: 0x00: Addr: 3C:71:BF:AB:19:4A [00:00:00.791] LOG -- hci.c.1906: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4 [00:00:00.802] LOG -- hci.c.1964: Packet types cc18, eSCO 1 [00:00:00.807] LOG -- hci.c.1967: BR/EDR support 1, LE support 1 [00:00:00.816] LOG -- hci.c.4181: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1 [00:00:00.820] LOG -- hci.c.1917: hci_le_read_buffer_size: size 251, count 10 [00:00:00.826] LOG -- hci.c.1756: Supported commands 30 [00:00:00.831] LOG -- hci.c.1924: hci_le_read_maximum_data_length: tx octets 251, tx time 2120 us [00:00:00.840] LOG -- hci.c.1930: hci_le_read_white_list_size: size 12 [00:00:00.846] LOG -- hci.c.1512: hci_init_done -> HCI_STATE_WORKING [00:00:00.852] LOG -- hci.c.4063: BTSTACK_EVENT_STATE 2 BTstack: up and running. [00:00:20.721] LOG -- hci.c.2076: Connection_incoming: A8:7D:12:01:BE:F1, type 1 [00:00:20.721] LOG -- hci.c.186: create_connection_for_addr A8:7D:12:01:BE:F1, type ff [00:00:20.725] LOG -- hci.c.3438: sending hci_accept_connection_request, remote eSCO 0 [00:00:20.912] LOG -- hci.c.2100: Connection_complete (status=0) A8:7D:12:01:BE:F1 [00:00:20.913] LOG -- hci.c.2113: New connection: handle 128, A8:7D:12:01:BE:F1 [00:00:20.916] LOG -- hci.c.4132: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1 [00:00:20.923] LOG -- hci.c.2162: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPLETE, bonding flags 6, eSCO 1 [00:00:20.932] LOG -- l2cap.c.1864: channel 0x3ffd1368, local_cid 0x0040 [00:00:20.938] LOG -- hci.c.4266: gap_request_security_level requested level 0, planned level 0, current level 0 [00:00:20.948] LOG -- hci.c.4163: hci_emit_security_level 0 for handle 80 [00:00:20.954] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:20.962] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0040 - state 5: actual 0 >= required 0? [00:00:20.971] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0x40 [00:00:20.983] LOG -- l2cap.c.2345: L2CAP_ACCEPT_CONNECTION local_cid 0x40 [00:00:20.991] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40 [00:00:20.996] LOG -- l2cap.c.1109: l2cap_start_rtx for local cid 0x40 [00:00:21.002] LOG -- l2cap.c.2550: L2CAP signaling handler code 4, state 11 [00:00:21.009] LOG -- l2cap.c.2401: Remote MTU 1024 [00:00:21.013] LOG -- l2cap.c.2550: L2CAP signaling handler code 5, state 11 [00:00:21.020] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40 [00:00:21.026] LOG -- l2cap.c.2481: l2cap_signaling_handle_configure_response [00:00:21.034] LOG -- l2cap.c.905: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0 [00:00:21.097] LOG -- hci.c.3491: IO Capability Request received, stack bondable 1, io cap 3 [00:00:21.098] LOG -- hci.c.4241: gap_mitm_protection_required_for_security_level 0 [00:00:21.380] LOG -- hid_mouse_demo.c.238: SSP User Confirmation Request with numeric value '182715'

[00:00:21.380] LOG -- hid_mouse_demo.c.239: SSP User Confirmation Auto accept

[00:00:21.853] LOG -- hci.c.388: gap_store_link_key_for_bd_addr: A8:7D:12:01:BE:F1, type 4 [00:00:21.853] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00 [00:00:21.856] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00 [00:00:21.862] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01 [00:00:21.868] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01 [00:00:21.873] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02 [00:00:21.880] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02 [00:00:21.885] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03 [00:00:21.892] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03 [00:00:21.897] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04 [00:00:21.904] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04 [00:00:21.909] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05 [00:00:21.915] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05 [00:00:21.921] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06 [00:00:21.927] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06 [00:00:21.933] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07 [00:00:21.939] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07 [00:00:21.945] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08 [00:00:21.951] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08 [00:00:21.957] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09 [00:00:21.963] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09 [00:00:21.969] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A [00:00:21.975] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A [00:00:21.981] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B [00:00:21.987] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B [00:00:21.992] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C [00:00:21.999] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C [00:00:22.004] LOG -- btstack_tlv_esp32.c.54: tag 42544c0d -> 42544C0D [00:00:22.011] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0D [00:00:22.017] LOG -- btstack_tlv_esp32.c.54: tag 42544c0e -> 42544C0E [00:00:22.022] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0E [00:00:22.028] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F [00:00:22.034] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0F [00:00:22.040] LOG -- btstack_link_key_db_tlv.c.151: tag_for_addr 42544c0f, tag_for_empy 42544c0c, tag_for_lowest_seq_nr 42544c0e [00:00:22.051] LOG -- btstack_link_key_db_tlv.c.165: store with tag 42544c0f [00:00:22.058] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F [00:00:22.064] LOG -- btstack_tlv_esp32.c.98: store tag 42544C0F [00:00:22.072] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80 [00:00:22.077] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:22.084] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0040 - state 12: actual 2 >= required 0? [00:00:22.132] LOG -- l2cap.c.2550: L2CAP signaling handler code 6, state 12 [00:00:22.133] LOG -- l2cap.c.933: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40 [00:00:22.135] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40 [00:00:22.169] LOG -- l2cap.c.1864: channel 0x3ffd1368, local_cid 0x0041 [00:00:22.169] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2 [00:00:22.174] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80 [00:00:22.181] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:22.188] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0041 - state 5: actual 2 >= required 2? [00:00:22.197] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x11 local_cid 0x41 remote_cid 0x41 [00:00:22.209] LOG -- l2cap.c.2345: L2CAP_ACCEPT_CONNECTION local_cid 0x41 [00:00:22.216] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41 [00:00:22.222] LOG -- l2cap.c.1109: l2cap_start_rtx for local cid 0x41 [00:00:22.228] LOG -- l2cap.c.2550: L2CAP signaling handler code 4, state 11 [00:00:22.235] LOG -- l2cap.c.2401: Remote MTU 672 [00:00:22.239] LOG -- l2cap.c.2550: L2CAP signaling handler code 5, state 11 [00:00:22.246] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41 [00:00:22.252] LOG -- l2cap.c.2481: l2cap_signaling_handle_configure_response [00:00:22.260] LOG -- l2cap.c.905: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x11 local_cid 0x41 remote_cid 0x41 local_mtu 100, remote_mtu 672, flush_timeout 0 [00:00:22.289] LOG -- l2cap.c.1864: channel 0x3ffd13d4, local_cid 0x0042 [00:00:22.289] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2 [00:00:22.295] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80 [00:00:22.301] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:22.309] LOG -- l2cap.c.2234: channel 0x3ffd13d4, cid 0042 - state 5: actual 2 >= required 2? [00:00:22.317] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x42 remote_cid 0x42 [00:00:22.330] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x42 [00:00:22.337] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x42 [00:00:22.343] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1 [00:00:22.353] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0041 - state 12: actual 2 >= required 2? [00:00:27.356] LOG -- l2cap.c.1864: channel 0x3ffd13d4, local_cid 0x0043 [00:00:27.357] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2 [00:00:27.362] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80 [00:00:27.368] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:27.376] LOG -- l2cap.c.2234: channel 0x3ffd13d4, cid 0043 - state 5: actual 2 >= required 2? [00:00:27.384] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x43 remote_cid 0x43 [00:00:27.397] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x43 [00:00:27.404] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x43 [00:00:27.410] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1 [00:00:27.420] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0041 - state 12: actual 2 >= required 2? [00:00:32.411] LOG -- l2cap.c.1864: channel 0x3ffd13d4, local_cid 0x0044 [00:00:32.412] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2 [00:00:32.417] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80 [00:00:32.423] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080 [00:00:32.431] LOG -- l2cap.c.2234: channel 0x3ffd13d4, cid 0044 - state 5: actual 2 >= required 2? [00:00:32.440] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x44 remote_cid 0x44 [00:00:32.452] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x44 [00:00:32.459] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x44 [00:00:32.465] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1 [00:00:32.475] LOG -- l2cap.c.2234: channel 0x3ffd1368, cid 0041 - state 12: actual 2 >= required 2? [00:00:32.484] LOG -- l2cap.c.2550: L2CAP signaling handler code 6, state 12 [00:00:32.491] LOG -- l2cap.c.933: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41 HID Disconnected [00:00:32.499] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41 [00:00:35.531] LOG -- hci.c.923: Connection closed: handle 0x80, A8:7D:12:01:BE:F1 [00:00:35.531] LOG -- hci.c.4132: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0`

fluffymadness commented 5 years ago

I enabled more advanced logging functions and disabled everything ble related in the btstack config header file, and in the main.c. Also I set the esp32 to bluetooth classic only mode with make menuconfig and in the main.c file of btstack. The BLE things which I disabled are listed in that issue (https://github.com/bluekitchen/btstack/issues/147), and here(https://groups.google.com/forum/#!topic/btstack-dev/ayDg-tyvlf4) Here is the new log of the keyboard hid demo with the disconnects. The log itselfs shows the pairing process of a windows 10 pc to the esp.

Toolchain path: /home/chainer/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-gcc
Toolchain version: crosstool-ng-1.22.0-80-g6c4433a
Compiler version: 5.2.0
Python requirements from /home/chainer/esp/esp-idf/requirements.txt are satisfied.
MONITOR
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5236
load:0x40078000,len:10876
load:0x40080400,len:6360
entry 0x4008070c
I (170) cpu_start: Pro cpu up.
I (171) cpu_start: Application information:
I (171) cpu_start: Project name:     hid_keyboard_demo
I (174) cpu_start: App version:      ad7cba71-dirty
I (179) cpu_start: Compile time:     Mar 25 2019 14:58:51
I (185) cpu_start: ELF file SHA256:  6b0eb06f6e706c8f...
I (191) cpu_start: ESP-IDF:          v4.0-dev-141-g106dc0590
I (198) cpu_start: Single core mode
I (202) heap_init: Initializing. RAM available for dynamic allocation:
I (209) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (215) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM
I (221) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (227) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (233) heap_init: At 3FFC82A0 len 00017D60 (95 KiB): DRAM
I (240) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM
I (246) heap_init: At 40078000 len 00008000 (32 KiB): IRAM
I (252) heap_init: At 40090850 len 0000F7B0 (61 KiB): IRAM
I (258) cpu_start: Pro cpu start user code
I (52) esp_core_dump_common: Init core dump to UART
E (53) esp_core_dump_common: No core dump partition found!
I (53) cpu_start: Starting scheduler on PRO CPU.
BTstack: setup
[00:00:00.061] LOG -- btstack_run_loop_freertos.c.260: run loop task 0x3ffbc0c4
[00:00:00.068] LOG -- btstack_run_loop_freertos.c.263: run loop init, queue item size 8
[00:00:00.075] LOG -- main.c.272: transport_register_packet_handler
[00:00:00.086] LOG -- btstack_tlv.c.48: TLV Instance 0x3f4079a4
[00:00:00.087] LOG -- l2cap.c.3512: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535
HID service record size: 247
Device ID SDP service record size: 64
[00:00:00.100] LOG -- l2cap.c.3512: L2CAP_REGISTER_SERVICE psm 0x13 mtu 100
[00:00:00.106] LOG -- l2cap.c.3512: L2CAP_REGISTER_SERVICE psm 0x11 mtu 100
[00:00:00.113] LOG -- hci.c.2931: hci_power_control: 1, current mode 0
[00:00:00.119] LOG -- main.c.204: transport_init
[00:00:00.124] LOG -- main.c.220: transport_open
I (128) BTDM_INIT: BT controller compile version [80351af]
I (135) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (224) phy: phy_version: 4100, 6fa5e27, Jan 25 2019, 17:02:06, 0, 0
[00:00:00.528] LOG -- main.c.251: transport: configure SCO over HCI, result 0x0000
[00:00:00.529] LOG -- hci.c.4063: BTSTACK_EVENT_STATE 1
[00:00:00.530] EVT <= 60 01 01 
[00:00:00.533] LOG -- hci.c.1203: hci_initializing_run: substate 0, can send 1
[00:00:00.540] CMD => 03 0C 00 
BTstack: execute run loop
[00:00:00.545] LOG -- btstack_run_loop_freertos.c.180: RL: execute
[00:00:00.551] EVT <= 6E 00 
[00:00:00.554] EVT <= 0E 04 05 03 0C 00 
[00:00:00.557] LOG -- hci.c.1528: Command complete for expected opcode 0c03 at substate 1
[00:00:00.565] LOG -- hci.c.1203: hci_initializing_run: substate 2, can send 1
[00:00:00.572] CMD => 01 10 00 
[00:00:00.575] EVT <= 0E 0C 05 01 10 00 08 0E 03 08 60 00 0E 03 
[00:00:00.580] LOG -- hci.c.1975: Manufacturer: 0x0060
[00:00:00.585] LOG -- hci.c.1528: Command complete for expected opcode 1001 at substate 3
[00:00:00.593] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.601] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.608] EVT <= 6E 00 
[00:00:00.611] LOG -- hci.c.1203: hci_initializing_run: substate 4, can send 1
[00:00:00.618] CMD => 14 0C 00 
[00:00:00.621] EVT <= 0E FC 05 14 0C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
[00:00:00.689] LOG -- hci.c.1889: local name: 
[00:00:00.693] LOG -- hci.c.1528: Command complete for expected opcode 0c14 at substate 5
[00:00:00.701] LOG -- hci.c.1648: Received local name, need baud change 0
[00:00:00.708] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.715] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.723] EVT <= 6E 00 
[00:00:00.725] LOG -- hci.c.1203: hci_initializing_run: substate 8, can send 1
[00:00:00.732] CMD => 02 10 00 
[00:00:00.735] EVT <= 0E 44 05 02 10 00 BF FF FF 03 CC FF EF FF 3F FF FC 1F F2 0F E8 FE 3F F7 8F FF 1C 00 04 00 61 F7 FF FF 7F 38 C0 FF 7F FF FF 0F 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
[00:00:00.755] LOG -- hci.c.1986: Local supported commands summary 0x3f
[00:00:00.762] LOG -- hci.c.1528: Command complete for expected opcode 1002 at substate 15
[00:00:00.770] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.777] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.785] EVT <= 6E 00 
[00:00:00.787] LOG -- hci.c.1203: hci_initializing_run: substate 22, can send 1
[00:00:00.794] CMD => 09 10 00 
[00:00:00.797] EVT <= 0E 0A 05 09 10 00 4A 19 AB BF 71 3C 
[00:00:00.803] LOG -- hci.c.1937: Local Address, Status: 0x00: Addr: 3C:71:BF:AB:19:4A
[00:00:00.810] LOG -- hci.c.1528: Command complete for expected opcode 1009 at substate 23
[00:00:00.818] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.826] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.833] EVT <= 6E 00 
[00:00:00.836] LOG -- hci.c.1203: hci_initializing_run: substate 24, can send 1
[00:00:00.843] CMD => 05 10 00 
[00:00:00.846] EVT <= 0E 0B 05 05 10 00 FD 03 FF 09 00 04 00 
[00:00:00.851] LOG -- hci.c.1906: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4
[00:00:00.862] LOG -- hci.c.1528: Command complete for expected opcode 1005 at substate 25
[00:00:00.870] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.877] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.885] EVT <= 6E 00 
[00:00:00.888] LOG -- hci.c.1203: hci_initializing_run: substate 26, can send 1
[00:00:00.895] CMD => 03 10 00 
[00:00:00.898] EVT <= 0E 0C 05 03 10 00 BF EE CD FE DB FF 7B 87 
[00:00:00.903] LOG -- hci.c.1964: Packet types cc18, eSCO 1
[00:00:00.909] LOG -- hci.c.1967: BR/EDR support 1, LE support 0
[00:00:00.914] LOG -- hci.c.1528: Command complete for expected opcode 1003 at substate 27
[00:00:00.922] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.930] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.937] EVT <= 6E 00 
[00:00:00.940] LOG -- hci.c.1203: hci_initializing_run: substate 28, can send 1
[00:00:00.947] CMD => 33 0C 07 00 04 3C 14 00 0A 00 
[00:00:00.952] EVT <= 0E 04 05 33 0C 00 
[00:00:00.955] LOG -- hci.c.1528: Command complete for expected opcode 0c33 at substate 29
[00:00:00.963] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:00.971] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:00.978] EVT <= 6E 00 
[00:00:00.981] LOG -- hci.c.1203: hci_initializing_run: substate 30, can send 1
[00:00:00.988] CMD => 31 0C 01 03 
[00:00:00.991] EVT <= 0E 04 05 31 0C 00 
[00:00:00.995] LOG -- hci.c.1528: Command complete for expected opcode 0c31 at substate 31
[00:00:01.003] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.010] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.018] EVT <= 6E 00 
[00:00:01.021] LOG -- hci.c.1203: hci_initializing_run: substate 32, can send 1
[00:00:01.028] CMD => 01 0C 08 FF FF FF FF FF FF FF 1F 
[00:00:01.033] EVT <= 0E 04 05 01 0C 00 
[00:00:01.036] LOG -- hci.c.1528: Command complete for expected opcode 0c01 at substate 33
[00:00:01.044] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.052] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.059] EVT <= 6E 00 
[00:00:01.062] LOG -- hci.c.1203: hci_initializing_run: substate 34, can send 1
[00:00:01.069] CMD => 56 0C 01 01 
[00:00:01.072] EVT <= 0E 04 05 56 0C 00 
[00:00:01.076] LOG -- hci.c.1528: Command complete for expected opcode 0c56 at substate 35
[00:00:01.084] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.091] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.099] EVT <= 6E 00 
[00:00:01.101] LOG -- hci.c.1203: hci_initializing_run: substate 36, can send 1
[00:00:01.108] CMD => 18 0C 02 00 60 
[00:00:01.112] EVT <= 0E 04 05 18 0C 00 
[00:00:01.115] LOG -- hci.c.1528: Command complete for expected opcode 0c18 at substate 37
[00:00:01.123] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.131] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.139] EVT <= 6E 00 
[00:00:01.141] LOG -- hci.c.1203: hci_initializing_run: substate 38, can send 1
[00:00:01.148] CMD => 0F 08 02 00 00 
[00:00:01.152] EVT <= 0E 04 05 0F 08 00 
[00:00:01.155] LOG -- hci.c.1528: Command complete for expected opcode 080f at substate 39
[00:00:01.163] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.171] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.178] EVT <= 6E 00 
[00:00:01.181] LOG -- hci.c.1203: hci_initializing_run: substate 40, can send 1
[00:00:01.188] CMD => 24 0C 03 40 25 00 
[00:00:01.192] EVT <= 0E 04 05 24 0C 00 
[00:00:01.195] LOG -- hci.c.1528: Command complete for expected opcode 0c24 at substate 41
[00:00:01.203] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.211] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.218] EVT <= 6E 00 
[00:00:01.221] LOG -- hci.c.1203: hci_initializing_run: substate 42, can send 1
[00:00:01.228] CMD => 13 0C F8 48 49 44 20 4B 65 79 62 6F 61 72 64 20 44 65 6D 6F 20 33 43 3A 37 31 3A 42 46 3A 41 42 3A 31 39 3A 34 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
[00:00:01.296] EVT <= 0E 04 05 13 0C 00 
[00:00:01.299] LOG -- hci.c.1528: Command complete for expected opcode 0c13 at substate 43
[00:00:01.307] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.314] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.322] EVT <= 6E 00 
[00:00:01.325] LOG -- hci.c.1203: hci_initializing_run: substate 44, can send 1
[00:00:01.332] CMD => 52 0C F1 00 24 09 48 49 44 20 4B 65 79 62 6F 61 72 64 20 44 65 6D 6F 20 33 43 3A 37 31 3A 42 46 3A 41 42 3A 31 39 3A 34 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
[00:00:01.398] EVT <= 0E 04 05 52 0C 00 
[00:00:01.401] LOG -- hci.c.1528: Command complete for expected opcode 0c52 at substate 45
[00:00:01.409] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.416] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.424] EVT <= 6E 00 
[00:00:01.427] LOG -- hci.c.1203: hci_initializing_run: substate 46, can send 1
[00:00:01.434] CMD => 45 0C 01 00 
[00:00:01.437] EVT <= 0E 04 05 45 0C 00 
[00:00:01.441] LOG -- hci.c.1528: Command complete for expected opcode 0c45 at substate 47
[00:00:01.449] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.456] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.464] EVT <= 6E 00 
[00:00:01.466] LOG -- hci.c.1203: hci_initializing_run: substate 48, can send 1
[00:00:01.473] CMD => 1A 0C 01 03 
[00:00:01.477] EVT <= 0E 04 05 1A 0C 00 
[00:00:01.480] LOG -- hci.c.4181: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1
[00:00:01.486] EVT <= 66 01 01 
[00:00:01.489] LOG -- hci.c.1528: Command complete for expected opcode 0c1a at substate 49
[00:00:01.497] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.504] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.512] EVT <= 6E 00 
[00:00:01.515] LOG -- hci.c.1203: hci_initializing_run: substate 50, can send 1
[00:00:01.522] CMD => 2F 0C 01 01 
[00:00:01.525] EVT <= 0E 04 05 2F 0C 00 
[00:00:01.529] LOG -- hci.c.1528: Command complete for expected opcode 0c2f at substate 51
[00:00:01.537] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.544] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.552] EVT <= 6E 00 
[00:00:01.554] LOG -- hci.c.1203: hci_initializing_run: substate 52, can send 1
[00:00:01.561] CMD => 5B 0C 01 01 
[00:00:01.565] EVT <= 0E 04 05 5B 0C 00 
[00:00:01.568] LOG -- hci.c.1528: Command complete for expected opcode 0c5b at substate 53
[00:00:01.576] LOG -- hci.c.1512: hci_init_done -> HCI_STATE_WORKING
[00:00:01.582] LOG -- hci.c.4063: BTSTACK_EVENT_STATE 2
[00:00:01.587] EVT <= 60 01 02 
BTstack: up and running.
[00:00:01.592] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.600] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:01.607] EVT <= 6E 00 
[00:00:01.610] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:01.617] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:06.028] EVT <= 04 0A F1 BE 01 12 7D A8 0C 01 0A 01 
[00:00:06.028] LOG -- hci.c.2076: Connection_incoming: A8:7D:12:01:BE:F1, type 1
[00:00:06.029] LOG -- hci.c.186: create_connection_for_addr A8:7D:12:01:BE:F1, type ff
[00:00:06.037] LOG -- hci.c.3438: sending hci_accept_connection_request, remote eSCO 0
[00:00:06.044] CMD => 09 04 07 F1 BE 01 12 7D A8 01 
[00:00:06.049] EVT <= 0F 04 00 05 09 04 
[00:00:06.053] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.060] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:06.068] EVT <= 6E 00 
[00:00:06.070] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.078] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:06.276] EVT <= 03 0B 00 80 00 F1 BE 01 12 7D A8 01 00 
[00:00:06.277] LOG -- hci.c.2100: Connection_complete (status=0) A8:7D:12:01:BE:F1
[00:00:06.278] LOG -- hci.c.2113: New connection: handle 128, A8:7D:12:01:BE:F1
[00:00:06.285] LOG -- hci.c.4132: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
[00:00:06.292] EVT <= 61 01 01 
[00:00:06.295] CMD => 1B 04 02 80 00 
[00:00:06.298] EVT <= 1B 03 80 00 05 
[00:00:06.301] ACL <= 80 20 0C 00 08 00 01 00 02 73 04 00 01 00 40 00 
[00:00:06.308] LOG -- l2cap.c.1864: channel 0x3ffcd4f8, local_cid 0x0040
[00:00:06.314] LOG -- hci.c.4266: gap_request_security_level requested level 0, planned level 0, current level 0
[00:00:06.324] LOG -- hci.c.4163: hci_emit_security_level 0 for handle 80
[00:00:06.330] EVT <= E0 03 80 00 00 
[00:00:06.334] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:06.341] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0040 - state 5: actual 0 >= required 0?
[00:00:06.350] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0x40
[00:00:06.362] EVT <= 72 0E F1 BE 01 12 7D A8 80 00 01 00 40 00 40 00 
[00:00:06.369] LOG -- l2cap.c.2345: L2CAP_ACCEPT_CONNECTION local_cid 0x40
[00:00:06.375] EVT <= 0F 04 00 05 1B 04 
[00:00:06.379] EVT <= 0B 0B 00 80 00 FF FE 0F FE DB FF 7B 87 
[00:00:06.384] LOG -- hci.c.2162: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPLETE, bonding flags 6, eSCO 1
[00:00:06.394] LOG -- l2cap.c.2217: remote supported features, channel 0x3ffcd4f8, cid 0040 - state 17
[00:00:06.403] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.410] LOG -- btstack_run_loop_freertos.c.210: RL: now 6410, expires 16279
[00:00:06.417] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9869
[00:00:06.425] EVT <= 6E 00 
[00:00:06.427] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.433] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.439] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.445] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:06.451] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:06.458] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:06.466] ACL => 80 00 10 00 0C 00 01 00 03 73 08 00 40 00 40 00 00 00 00 00 
[00:00:06.474] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:06.482] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:06.489] EVT <= 13 05 01 80 00 01 00 
[00:00:06.493] ACL <= 80 20 10 00 0C 00 01 00 04 74 08 00 40 00 00 00 01 02 00 04 
[00:00:06.500] LOG -- l2cap.c.2550: L2CAP signaling handler code 4, state 11
[00:00:06.507] LOG -- l2cap.c.2401: Remote MTU 1024
[00:00:06.511] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.519] LOG -- btstack_run_loop_freertos.c.210: RL: now 6519, expires 16279
[00:00:06.526] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9760
[00:00:06.533] EVT <= 6E 00 
[00:00:06.536] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.542] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.547] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.553] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:06.559] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:06.566] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:06.575] ACL => 80 00 12 00 0E 00 01 00 05 74 0A 00 40 00 00 00 00 00 01 02 00 04 
[00:00:06.583] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:06.591] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:06.598] EVT <= 13 05 01 80 00 01 00 
[00:00:06.602] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.609] LOG -- btstack_run_loop_freertos.c.210: RL: now 6609, expires 16279
[00:00:06.616] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9670
[00:00:06.623] EVT <= 6E 00 
[00:00:06.626] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.632] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.638] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:06.643] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:06.650] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:06.656] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:06.665] ACL => 80 00 10 00 0C 00 01 00 04 01 08 00 40 00 00 00 01 02 9B 06 
[00:00:06.672] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:06.681] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:06.687] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40
[00:00:06.694] LOG -- l2cap.c.1109: l2cap_start_rtx for local cid 0x40
[00:00:06.700] EVT <= 13 05 01 80 00 01 00 
[00:00:06.704] ACL <= 80 20 12 00 0E 00 01 00 05 01 0A 00 40 00 00 00 00 00 01 02 00 04 
[00:00:06.712] LOG -- l2cap.c.2550: L2CAP signaling handler code 5, state 11
[00:00:06.718] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40
[00:00:06.724] LOG -- l2cap.c.2481: l2cap_signaling_handle_configure_response
[00:00:06.731] LOG -- l2cap.c.905: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x1 local_cid 0x40 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0
[00:00:06.748] EVT <= 70 18 00 F1 BE 01 12 7D A8 80 00 01 00 40 00 40 00 9B 06 00 04 00 00 01 00 00 
[00:00:06.757] EVT <= 32 09 F1 BE 01 12 7D A8 01 00 05 
[00:00:06.762] EVT <= 31 06 F1 BE 01 12 7D A8 
[00:00:06.766] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.774] LOG -- btstack_run_loop_freertos.c.210: RL: now 6774, expires 16279
[00:00:06.781] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9505
[00:00:06.788] EVT <= 6E 00 
[00:00:06.791] CMD => 35 0C 05 01 80 00 03 00 
[00:00:06.795] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.802] LOG -- btstack_run_loop_freertos.c.210: RL: now 6802, expires 16279
[00:00:06.810] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9477
[00:00:06.817] EVT <= 6E 00 
[00:00:06.820] LOG -- hci.c.3491: IO Capability Request received, stack bondable 1, io cap 3
[00:00:06.828] LOG -- hci.c.4241: gap_mitm_protection_required_for_security_level 0
[00:00:06.835] CMD => 2B 04 09 F1 BE 01 12 7D A8 03 00 04 
[00:00:06.840] EVT <= 0E 0A 05 2B 04 00 F1 BE 01 12 7D A8 
[00:00:06.846] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.853] LOG -- btstack_run_loop_freertos.c.210: RL: now 6853, expires 16279
[00:00:06.860] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9426
[00:00:06.867] EVT <= 6E 00 
[00:00:06.908] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:06.909] LOG -- btstack_run_loop_freertos.c.210: RL: now 6909, expires 16279
[00:00:06.912] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9370
[00:00:07.081] EVT <= 33 0A F1 BE 01 12 7D A8 47 B0 0A 00 
[00:00:07.082] LOG -- hid_keyboard_demo.c.320: SSP User Confirmation Request with numeric value '700487'

[00:00:07.085] LOG -- hid_keyboard_demo.c.321: SSP User Confirmation Auto accept

[00:00:07.092] CMD => 2C 04 06 F1 BE 01 12 7D A8 
[00:00:07.097] EVT <= 0E 0A 05 2C 04 00 F1 BE 01 12 7D A8 
[00:00:07.102] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:07.109] LOG -- btstack_run_loop_freertos.c.210: RL: now 7109, expires 16279
[00:00:07.117] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9170
[00:00:07.124] EVT <= 6E 00 
[00:00:07.126] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:07.134] LOG -- btstack_run_loop_freertos.c.210: RL: now 7134, expires 16279
[00:00:07.141] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 9145
[00:00:07.416] EVT <= 36 07 00 F1 BE 01 12 7D A8 
[00:00:07.417] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:07.417] LOG -- btstack_run_loop_freertos.c.210: RL: now 7417, expires 16279
[00:00:07.425] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8862
[00:00:07.444] EVT <= 18 17 F1 BE 01 12 7D A8 04 3E 48 27 94 79 4A 5C 08 2F C9 F4 F8 42 B5 ED 04 
[00:00:07.445] LOG -- hci.c.388: gap_store_link_key_for_bd_addr: A8:7D:12:01:BE:F1, type 4
[00:00:07.451] LOG -- btstack_tlv_esp32.c.54: tag 42544c00 -> 42544C00
[00:00:07.457] LOG -- btstack_tlv_esp32.c.68: read tag 42544C00
[00:00:07.463] LOG -- btstack_tlv_esp32.c.54: tag 42544c01 -> 42544C01
[00:00:07.469] LOG -- btstack_tlv_esp32.c.68: read tag 42544C01
[00:00:07.474] LOG -- btstack_tlv_esp32.c.54: tag 42544c02 -> 42544C02
[00:00:07.481] LOG -- btstack_tlv_esp32.c.68: read tag 42544C02
[00:00:07.486] LOG -- btstack_tlv_esp32.c.54: tag 42544c03 -> 42544C03
[00:00:07.493] LOG -- btstack_tlv_esp32.c.68: read tag 42544C03
[00:00:07.498] LOG -- btstack_tlv_esp32.c.54: tag 42544c04 -> 42544C04
[00:00:07.504] LOG -- btstack_tlv_esp32.c.68: read tag 42544C04
[00:00:07.510] LOG -- btstack_tlv_esp32.c.54: tag 42544c05 -> 42544C05
[00:00:07.516] LOG -- btstack_tlv_esp32.c.68: read tag 42544C05
[00:00:07.522] LOG -- btstack_tlv_esp32.c.54: tag 42544c06 -> 42544C06
[00:00:07.528] LOG -- btstack_tlv_esp32.c.68: read tag 42544C06
[00:00:07.534] LOG -- btstack_tlv_esp32.c.54: tag 42544c07 -> 42544C07
[00:00:07.540] LOG -- btstack_tlv_esp32.c.68: read tag 42544C07
[00:00:07.546] LOG -- btstack_tlv_esp32.c.54: tag 42544c08 -> 42544C08
[00:00:07.552] LOG -- btstack_tlv_esp32.c.68: read tag 42544C08
[00:00:07.558] LOG -- btstack_tlv_esp32.c.54: tag 42544c09 -> 42544C09
[00:00:07.564] LOG -- btstack_tlv_esp32.c.68: read tag 42544C09
[00:00:07.570] LOG -- btstack_tlv_esp32.c.54: tag 42544c0a -> 42544C0A
[00:00:07.576] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0A
[00:00:07.581] LOG -- btstack_tlv_esp32.c.54: tag 42544c0b -> 42544C0B
[00:00:07.588] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0B
[00:00:07.593] LOG -- btstack_tlv_esp32.c.54: tag 42544c0c -> 42544C0C
[00:00:07.600] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0C
[00:00:07.605] LOG -- btstack_tlv_esp32.c.54: tag 42544c0d -> 42544C0D
[00:00:07.611] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0D
[00:00:07.618] LOG -- btstack_tlv_esp32.c.54: tag 42544c0e -> 42544C0E
[00:00:07.623] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0E
[00:00:07.629] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F
[00:00:07.635] LOG -- btstack_tlv_esp32.c.68: read tag 42544C0F
[00:00:07.641] LOG -- btstack_link_key_db_tlv.c.151: tag_for_addr 42544c0f, tag_for_empy 42544c0c, tag_for_lowest_seq_nr 42544c0e
[00:00:07.652] LOG -- btstack_link_key_db_tlv.c.165: store with tag 42544c0f
[00:00:07.659] LOG -- btstack_tlv_esp32.c.54: tag 42544c0f -> 42544C0F
[00:00:07.665] LOG -- btstack_tlv_esp32.c.98: store tag 42544C0F
[00:00:07.673] EVT <= 08 04 00 80 00 01 
[00:00:07.675] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80
[00:00:07.681] EVT <= E0 03 80 00 02 
[00:00:07.685] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:07.692] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0040 - state 12: actual 2 >= required 0?
[00:00:07.701] ACL <= 80 20 18 00 14 00 40 00 06 00 00 00 0F 35 03 19 01 00 03 F8 35 05 0A 00 00 FF FF 00 
[00:00:07.711] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.716] LOG -- l2cap.c.877: L2CAP_EVENT_CHANNEL_CAN_SEND_NOW local_cid 0x40
[00:00:07.723] EVT <= 78 02 40 00 
[00:00:07.726] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.732] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.738] LOG -- l2cap.c.1168: l2cap_send_prepared cid 0x40, handle 128, 1 credit used
[00:00:07.746] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.752] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:07.758] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:07.765] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:07.774] ACL => 80 00 06 01 02 01 40 00 07 00 00 00 FD 00 FA 36 00 F7 36 00 F4 09 00 00 0A 00 01 00 01 09 00 01 36 00 03 19 11 24 09 00 04 36 00 0F 36 00 06 19 01 00 09 00 11 36 00 03 19 00 11 09 00 06 36 00 09 09 65 6E 09 00 6A 09 01 00 09 00 0D 36 00 12 36 00 0F 36 00 06 19 01 00 09 00 13 36 00 03 19 00 11 09 01 00 25 14 42 54 73 74 61 63 6B 20 48 49 44 20 4B 65 79 62 6F 61 72 64 09 00 09 36 00 09 36 00 06 19 11 24 09 01 01 09 02 01 09 01 11 09 02 02 08 40 09 02 03 08 21 09 02 04 28 00 09 02 05 28 00 09 02 06 36 00 46 36 00 43 08 22 25 3F 05 01 09 06 A1 01 75 01 95 08 05 07 19 E0 29 E7 15 00 25 01 81 02 75 01 95 08 81 03 95 05 75 01 05 08 19 01 29 05 91 02 95 01 75 03 91 03 95 06 75 08 15 00 25 FF 05 07 19 00 29 FF 81 00 C0 09 02 07 36 00 09 36 00 06 09 04 09 09 01 00 09 02 0A 28 01 09 02 0E 28 00 00 
[00:00:07.845] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:07.853] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:07.860] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:07.867] LOG -- btstack_run_loop_freertos.c.210: RL: now 7867, expires 16279
[00:00:07.875] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8412
[00:00:07.882] EVT <= 6E 00 
[00:00:07.884] CMD => 35 0C 05 01 80 00 01 00 
[00:00:07.889] EVT <= 13 05 01 80 00 01 00 
[00:00:07.892] ACL <= 80 20 18 00 14 00 40 00 06 00 01 00 0F 35 03 19 12 00 03 F8 35 05 0A 02 01 02 05 00 
[00:00:07.902] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:07.909] LOG -- btstack_run_loop_freertos.c.210: RL: now 7909, expires 16279
[00:00:07.916] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8370
[00:00:07.924] EVT <= 6E 00 
[00:00:07.926] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.932] LOG -- l2cap.c.877: L2CAP_EVENT_CHANNEL_CAN_SEND_NOW local_cid 0x40
[00:00:07.939] EVT <= 78 02 40 00 
[00:00:07.943] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.948] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.954] LOG -- l2cap.c.1168: l2cap_send_prepared cid 0x40, handle 128, 1 credit used
[00:00:07.962] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:07.968] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:07.974] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:07.981] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:07.990] ACL => 80 00 2F 00 2B 00 40 00 07 00 01 00 26 00 23 36 00 20 36 00 1D 09 02 01 09 04 8F 09 02 02 09 00 01 09 02 03 09 00 01 09 02 04 28 01 09 02 05 09 00 01 00 
[00:00:08.005] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.014] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.020] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.027] LOG -- btstack_run_loop_freertos.c.210: RL: now 8027, expires 16279
[00:00:08.035] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8252
[00:00:08.042] EVT <= 6E 00 
[00:00:08.045] CMD => 35 0C 05 01 80 00 01 00 
[00:00:08.049] EVT <= 13 05 01 80 00 01 00 
[00:00:08.053] ACL <= 80 20 0C 00 08 00 01 00 06 75 04 00 40 00 40 00 
[00:00:08.059] LOG -- l2cap.c.2550: L2CAP signaling handler code 6, state 12
[00:00:08.066] ACL <= 80 20 0C 00 08 00 01 00 02 76 04 00 11 00 41 00 
[00:00:08.072] LOG -- l2cap.c.1864: channel 0x3ffcd5dc, local_cid 0x0041
[00:00:08.078] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2
[00:00:08.088] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80
[00:00:08.095] EVT <= E0 03 80 00 02 
[00:00:08.098] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:08.105] LOG -- l2cap.c.2234: channel 0x3ffcd5dc, cid 0041 - state 5: actual 2 >= required 2?
[00:00:08.114] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x11 local_cid 0x41 remote_cid 0x41
[00:00:08.127] EVT <= 72 0E F1 BE 01 12 7D A8 80 00 11 00 41 00 41 00 
[00:00:08.133] LOG -- l2cap.c.2345: L2CAP_ACCEPT_CONNECTION local_cid 0x41
[00:00:08.140] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0040 - state 19: actual 2 >= required 0?
[00:00:08.148] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.156] LOG -- btstack_run_loop_freertos.c.210: RL: now 8156, expires 16279
[00:00:08.163] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8123
[00:00:08.170] EVT <= 6E 00 
[00:00:08.173] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.179] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.185] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.190] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:08.197] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:08.203] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:08.212] ACL => 80 00 10 00 0C 00 01 00 03 76 08 00 41 00 41 00 00 00 00 00 
[00:00:08.219] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.228] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.234] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.242] LOG -- btstack_run_loop_freertos.c.210: RL: now 8242, expires 16279
[00:00:08.249] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 8037
[00:00:08.256] EVT <= 6E 00 
[00:00:08.259] LOG -- hci.c.460: ACL classic buffers: 1 used of 9
[00:00:08.265] LOG -- hci.c.460: ACL classic buffers: 1 used of 9
[00:00:08.270] LOG -- hci.c.460: ACL classic buffers: 1 used of 9
[00:00:08.276] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:08.282] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:08.289] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:08.298] ACL => 80 00 10 00 0C 00 01 00 04 02 08 00 41 00 00 00 01 02 64 00 
[00:00:08.305] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.314] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.320] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41
[00:00:08.326] LOG -- l2cap.c.1109: l2cap_start_rtx for local cid 0x41
[00:00:08.333] EVT <= 13 05 01 80 00 01 00 
[00:00:08.336] ACL <= 80 20 10 00 0C 00 01 00 04 77 08 00 41 00 00 00 01 02 A0 02 
[00:00:08.344] LOG -- l2cap.c.2550: L2CAP signaling handler code 4, state 11
[00:00:08.350] LOG -- l2cap.c.2401: Remote MTU 672
[00:00:08.355] EVT <= 13 05 01 80 00 01 00 
[00:00:08.359] ACL <= 80 20 0E 00 0A 00 01 00 05 02 06 00 41 00 00 00 00 00 
[00:00:08.366] LOG -- l2cap.c.2550: L2CAP signaling handler code 5, state 11
[00:00:08.372] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41
[00:00:08.379] LOG -- l2cap.c.2481: l2cap_signaling_handle_configure_response
[00:00:08.385] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.393] LOG -- btstack_run_loop_freertos.c.210: RL: now 8393, expires 16279
[00:00:08.400] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7886
[00:00:08.407] EVT <= 6E 00 
[00:00:08.410] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.416] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.422] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.427] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:08.434] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:08.440] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:08.449] ACL => 80 00 12 00 0E 00 01 00 05 77 0A 00 41 00 00 00 00 00 01 02 64 00 
[00:00:08.457] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.465] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.472] LOG -- l2cap.c.905: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x11 local_cid 0x41 remote_cid 0x41 local_mtu 100, remote_mtu 672, flush_timeout 0
[00:00:08.489] EVT <= 70 18 00 F1 BE 01 12 7D A8 80 00 11 00 41 00 41 00 64 00 A0 02 00 00 01 00 00 
[00:00:08.498] EVT <= 13 05 01 80 00 01 00 
[00:00:08.502] EVT <= 0D 15 00 80 00 00 01 D4 8E 01 00 00 00 00 00 10 27 00 00 FF FF FF FF 
[00:00:08.510] ACL <= 80 20 0C 00 08 00 01 00 02 78 04 00 13 00 42 00 
[00:00:08.516] LOG -- l2cap.c.1864: channel 0x3ffcd648, local_cid 0x0042
[00:00:08.522] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2
[00:00:08.532] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80
[00:00:08.539] EVT <= E0 03 80 00 02 
[00:00:08.542] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:08.549] LOG -- l2cap.c.2234: channel 0x3ffcd648, cid 0042 - state 5: actual 2 >= required 2?
[00:00:08.558] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x42 remote_cid 0x42
[00:00:08.571] EVT <= 72 0E F1 BE 01 12 7D A8 80 00 13 00 42 00 42 00 
[00:00:08.577] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x42
[00:00:08.584] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1
[00:00:08.594] LOG -- l2cap.c.2234: channel 0x3ffcd5dc, cid 0041 - state 12: actual 2 >= required 2?
[00:00:08.602] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0040 - state 19: actual 2 >= required 0?
[00:00:08.611] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.619] LOG -- btstack_run_loop_freertos.c.210: RL: now 8619, expires 16279
[00:00:08.626] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7660
[00:00:08.633] EVT <= 6E 00 
[00:00:08.636] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.642] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.647] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.653] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:08.659] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:08.666] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:08.675] ACL => 80 00 10 00 0C 00 01 00 03 78 08 00 42 00 42 00 04 00 00 00 
[00:00:08.682] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.691] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.697] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x42
[00:00:08.703] EVT <= 13 05 01 80 00 01 00 
[00:00:08.707] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.715] LOG -- btstack_run_loop_freertos.c.210: RL: now 8715, expires 16279
[00:00:08.722] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7564
[00:00:08.729] EVT <= 6E 00 
[00:00:08.732] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.737] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.743] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:08.749] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:08.755] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:08.762] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:08.771] ACL => 80 00 0C 00 08 00 01 00 07 75 04 00 40 00 40 00 
[00:00:08.777] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:08.786] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:08.792] LOG -- l2cap.c.933: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x40
[00:00:08.799] EVT <= 71 02 40 00 
[00:00:08.802] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x40
[00:00:08.808] EVT <= 13 05 01 80 00 01 00 
[00:00:08.812] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.819] LOG -- btstack_run_loop_freertos.c.210: RL: now 8819, expires 16279
[00:00:08.827] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7460
[00:00:08.834] EVT <= 6E 00 
[00:00:08.836] CMD => 35 0C 05 01 80 00 05 00 
[00:00:08.841] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.848] LOG -- btstack_run_loop_freertos.c.210: RL: now 8848, expires 16279
[00:00:08.855] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7431
[00:00:08.862] EVT <= 6E 00 
[00:00:08.865] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:08.872] LOG -- btstack_run_loop_freertos.c.210: RL: now 8872, expires 16279
[00:00:08.880] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 7407
[00:00:13.754] ACL <= 80 20 0C 00 08 00 01 00 02 79 04 00 13 00 43 00 
[00:00:13.754] LOG -- l2cap.c.1864: channel 0x3ffcd4f8, local_cid 0x0043
[00:00:13.756] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2
[00:00:13.766] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80
[00:00:13.772] EVT <= E0 03 80 00 02 
[00:00:13.776] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:13.783] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0043 - state 5: actual 2 >= required 2?
[00:00:13.792] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x43 remote_cid 0x43
[00:00:13.804] EVT <= 72 0E F1 BE 01 12 7D A8 80 00 13 00 43 00 43 00 
[00:00:13.810] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x43
[00:00:13.817] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:13.823] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:13.829] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:13.835] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:13.841] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:13.848] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:13.856] ACL => 80 00 10 00 0C 00 01 00 03 79 08 00 43 00 43 00 04 00 00 00 
[00:00:13.864] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:13.872] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:13.878] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x43
[00:00:13.885] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1
[00:00:13.895] LOG -- l2cap.c.2234: channel 0x3ffcd5dc, cid 0041 - state 12: actual 2 >= required 2?
[00:00:13.904] EVT <= 13 05 01 80 00 01 00 
[00:00:13.907] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:13.915] LOG -- btstack_run_loop_freertos.c.210: RL: now 13915, expires 16279
[00:00:13.922] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 2364
[00:00:13.929] EVT <= 6E 00 
[00:00:13.932] CMD => 35 0C 05 01 80 00 01 00 
[00:00:13.936] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:13.944] LOG -- btstack_run_loop_freertos.c.210: RL: now 13944, expires 16279
[00:00:13.951] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 2335
[00:00:13.958] EVT <= 6E 00 
[00:00:13.961] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:13.968] LOG -- btstack_run_loop_freertos.c.210: RL: now 13968, expires 16279
[00:00:13.975] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 2311
[00:00:16.294] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:16.294] LOG -- btstack_run_loop_freertos.c.210: RL: now 16294, expires 16279
[00:00:16.297] LOG -- btstack_run_loop_freertos.c.217: RL: first timer 0x400e3490
[00:00:16.304] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:18.934] ACL <= 80 20 0C 00 08 00 01 00 02 7A 04 00 13 00 44 00 
[00:00:18.935] LOG -- l2cap.c.1864: channel 0x3ffcd4f8, local_cid 0x0044
[00:00:18.936] LOG -- hci.c.4266: gap_request_security_level requested level 2, planned level 0, current level 2
[00:00:18.946] LOG -- hci.c.4163: hci_emit_security_level 2 for handle 80
[00:00:18.952] EVT <= E0 03 80 00 02 
[00:00:18.956] LOG -- l2cap.c.2224: l2cap - security level update for handle 0x0080
[00:00:18.963] LOG -- l2cap.c.2234: channel 0x3ffcd4f8, cid 0044 - state 5: actual 2 >= required 2?
[00:00:18.972] LOG -- l2cap.c.939: L2CAP_EVENT_INCOMING_CONNECTION addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x44 remote_cid 0x44
[00:00:18.984] EVT <= 72 0E F1 BE 01 12 7D A8 80 00 13 00 44 00 44 00 
[00:00:18.991] LOG -- l2cap.c.2364: L2CAP_DECLINE_CONNECTION local_cid 0x44
[00:00:18.997] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.003] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.009] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.015] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:19.021] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:19.028] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:19.036] ACL => 80 00 10 00 0C 00 01 00 03 7A 08 00 44 00 44 00 04 00 00 00 
[00:00:19.044] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:19.052] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:19.059] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x44
[00:00:19.065] LOG -- hid_device.c.667: L2CAP_EVENT_INCOMING_CONNECTION, decline connection for A8:7D:12:01:BE:F1
[00:00:19.075] LOG -- l2cap.c.2234: channel 0x3ffcd5dc, cid 0041 - state 12: actual 2 >= required 2?
[00:00:19.084] EVT <= 13 05 01 80 00 01 00 
[00:00:19.088] ACL <= 80 20 0C 00 08 00 01 00 06 7B 04 00 41 00 41 00 
[00:00:19.094] LOG -- l2cap.c.2550: L2CAP signaling handler code 6, state 12
[00:00:19.101] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:19.108] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:19.116] EVT <= 6E 00 
[00:00:19.118] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.124] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.130] LOG -- hci.c.460: ACL classic buffers: 0 used of 9
[00:00:19.136] LOG -- hci.c.648: hci_send_acl_packet_fragments entered
[00:00:19.142] LOG -- hci.c.654: hci_send_acl_packet_fragments loop entered
[00:00:19.149] LOG -- hci.c.679: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:19.157] ACL => 80 00 0C 00 08 00 01 00 07 7B 04 00 41 00 41 00 
[00:00:19.164] LOG -- hci.c.698: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:19.172] LOG -- hci.c.707: hci_send_acl_packet_fragments loop over
[00:00:19.179] LOG -- l2cap.c.933: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41
[00:00:19.185] EVT <= 71 02 41 00 
HID Disconnected
[00:00:19.190] LOG -- l2cap.c.1100: l2cap_stop_rtx for local cid 0x41
[00:00:19.196] EVT <= 13 05 01 80 00 01 00 
[00:00:19.200] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:19.208] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:19.215] EVT <= 6E 00 
[00:00:19.218] CMD => 35 0C 05 01 80 00 02 00 
[00:00:19.222] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:19.229] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:19.237] EVT <= 6E 00 
[00:00:19.240] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:19.247] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
[00:00:22.264] EVT <= 05 04 00 80 00 13 
[00:00:22.265] LOG -- hci.c.923: Connection closed: handle 0x80, A8:7D:12:01:BE:F1
[00:00:22.265] LOG -- hci.c.4132: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0
[00:00:22.271] EVT <= 61 01 00 
[00:00:22.274] LOG -- btstack_run_loop_freertos.c.206: RL: portMAX_DELAY 4294967295
[00:00:22.281] LOG -- btstack_run_loop_freertos.c.222: RL: wait with timeout 4294967295
mringwal commented 5 years ago

thanks for the extended version. You can disable ENABLE_LOG_DEBUG, it's really a last resort and adds a lot of noise. Could you convert the text log into PacketLogger format with btstack/tool/create_packet_log.py (and post it here)? It can then be opened & analyzed with Wireshark.

fluffymadness commented 5 years ago

Thanks for your quick response. The log is the pairing request from my windows 10 computer to the esp32 hid keyboard example. It says connected in the windows 10 bluetooth settings after pairing. This state stays for about 10secs then it jumps right to "device paired" loosing the connection. hci_dump_keyboard.zip

fluffymadness commented 5 years ago

Hope the conversion worked. I just redirected the output of "make monitor" > test.log and made the conversion with the python utility. edit: just opened the dump in wireshark. seems fine

mringwal commented 5 years ago

The conversion worked. BTstack rejects the incoming HID Interrupt connection, which is a bug. Are you on the master or the develop branch? If on master, please switch to develop and try again. (although there might be another issue, need to double check that).

fluffymadness commented 5 years ago

I'm on the master branch. I'll try switching to dev.

fluffymadness commented 5 years ago

it goes further now on the develop branch....Says "HID Connected, please start typing..."..but it stacktraces

[00:00:20.882] LOG -- l2cap.c.905: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr A8:7D:12:01:BE:F1 handle 0x80 psm 0x13 local_cid 0x42 remote_cid 0x42 local_mtu 100, remote_mtu 672, flush_timeout 0 HID Connected, please start typing... Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled. Core 0 register dump: PC : 0x400fd1bf PS : 0x00060a30 A0 : 0x800fd76e A1 : 0x3ffbbde0 0x400fd1bf: hid_device_request_can_send_now_event at /home/chainer/esp/esp-idf/components/btstack/src/classic/hid_device.c:996

A2 : 0x00000041 A3 : 0x3ffd144c A4 : 0x3ffc1724 A5 : 0x00000080 A6 : 0x00000001 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x3ffbbdc0 A10 : 0x00000000 A11 : 0x00060823 A12 : 0x00060820 A13 : 0x00000000 A14 : 0x00000000 A15 : 0x02070903 SAR : 0x00000010 EXCCAUSE: 0x0000001d EXCVADDR: 0x00000010 LBEG : 0x4000c349 LEND : 0x4000c36b LCOUNT : 0xffffffff

ELF file SHA256: 3f9a8fee8dbb2eaa71b87831a27f849344033cc28c5420ff2ad384f241ea6d47

Backtrace: 0x400fd1bf:0x3ffbbde0 0x400fd76b:0x3ffbbe00 0x4010a33a:0x3ffbbe70 0x400fffad:0x3ffbbe90 0x400fffdd:0x3ffbbeb0 0x400e3101:0x3ffbbed0 0x400e6cd9:0x3ffbbef0 0x400e6e66:0x3ffbbf30 0x400e29e4:0x3ffbbf50 0x400e2a35:0x3ffbbf80 0x400e7ba1:0x3ffbbfa0 0x400e766d:0x3ffbbfd0 0x400e2b6c:0x3ffbbff0 0x400d17f4:0x3ffbc010 0x4008d22d:0x3ffbc030 0x400fd1bf: hid_device_request_can_send_now_event at /home/chainer/esp/esp-idf/components/btstack/src/classic/hid_device.c:996

0x400fd76b: packet_handler at /home/chainer/esp/esp-idf/components/btstack/src/classic/hid_device.c:631

0x4010a33a: l2cap_dispatch_to_channel at /home/chainer/esp/esp-idf/components/btstack/src/l2cap.c:1229

0x400fffad: l2cap_acl_classic_handler at /home/chainer/esp/esp-idf/components/btstack/src/l2cap.c:1229

0x400fffdd: l2cap_acl_handler at /home/chainer/esp/esp-idf/components/btstack/src/l2cap.c:1229

0x400e3101: hci_emit_acl_packet at /home/chainer/esp/esp-idf/components/btstack/src/hci.c:4305

0x400e6cd9: acl_handler at /home/chainer/esp/esp-idf/components/btstack/src/hci.c:4305

0x400e6e66: packet_handler at /home/chainer/esp/esp-idf/components/btstack/src/hci.c:4305

0x400e29e4: transport_deliver_packets at /home/chainer/esp/esp-idf/components/btstack/main.c:175

0x400e2a35: transport_process at /home/chainer/esp/esp-idf/components/btstack/main.c:191

0x400e7ba1: btstack_run_loop_freertos_execute at /home/chainer/esp/esp-idf/components/btstack/platform/freertos/btstack_run_loop_freertos.c:172

0x400e766d: btstack_run_loop_execute at /home/chainer/esp/esp-idf/components/btstack/src/btstack_run_loop.c:189

0x400e2b6c: app_main at /home/chainer/esp/esp-idf/components/btstack/main.c:394

0x400d17f4: main_task at /home/chainer/esp/esp-idf/components/esp32/cpu_start.c:530

0x4008d22d: vPortTaskWrapper at /home/chainer/esp/esp-idf/components/freertos/port.c:403

mringwal commented 5 years ago

ok, that might be the other issue... I'll try to have a look this week and post and post and update here.

fluffymadness commented 5 years ago

thanks.

mringwal commented 5 years ago

Hm. I've tried hid_keyboard_demo both on Mac (libusb) and ESP32. It worked fine. Could you use the code from current develop without modifications (in the current code, there's no line 996 "hid_device_request_can_send_now_event at /home/chainer/esp/esp-idf/components/btstack/src/classic/hid_device.c:996"). If it still/again crashes, please post the .pklg again.

fluffymadness commented 5 years ago

Steps that I did:

Here is the log: newlog.zip

Did you build the example with the latest commit of the esp-idf or are you on an older maybe more stable version?

As for this line, /home/chainer/esp/esp-idf/components/btstack/src/classic/hid_device.c:996....I'm wondering myself, because it is, as you said, not in the code. I checked the file in this directory and line 996 is: l2cap_disconnect(hid_device->control_cid, 0); // reason isn't used

Thanks again for helping me.

mringwal commented 5 years ago

Thanks for the retry and the log. In the new log, there's no hint of a null pointer access. Up to the crash, everything looks fine to me.

I did use the current master branch, 5beb2802 (from Sun March 17).

Could you try to connect from another device, e.g. a smartphone? (don't have a better idea at the moment..)

fluffymadness commented 5 years ago

Using another device did the trick. Connecting from my phone works. The same is with linux. Keyboard example is doing fine then. Connecting via Windows 10 instant stack-traces everything...doesn't matter if I use the internal bluetooth of my notebook or an usb bluetooth stick. That's interresting.

mringwal commented 5 years ago

Interesting! Maybe it's a NULL pointer after all.

Thanks for helping with testing and sorry I couldn't test with Windows myself yet. I hope to get to that this week somehow.

fluffymadness commented 5 years ago

I'm happy to help. Hopefully the bug is somehow reproducible. Another thing I've noticed is when doing an sdp tool query on linux the connection never terminates after I get the records of the bluetooth device (keyboard example). It goes on until I manually kill sdptool. When I tested this with a dualshock 4 and a bluetooth audio receiver, the connection terminated after 5-10 seconds when I got the sdp records.

mringwal commented 5 years ago

Hi! I've found the bug, it really was BTstack's fault. After the last change, incoming HID requests (e.g. the one from Windows) directly caused a NULL pointer access. Please update develop, try again, and let me know.

For the Linux SDP tool: could you enable HCI logging again and post a .pklg file.

fluffymadness commented 5 years ago

Hi. Thanks for fixing the bug. I'll try to get to testing this week.

www378660084 commented 5 years ago

"pull request 207" fixs the bug

mringwal commented 5 years ago

@www378660084 see comment on your pull request. Code on develop has the fix.

fluffymadness commented 5 years ago

Windows 10 is working fine now, but I have another problem when trying to re-build the hid keyboard example. I made a make clean before the make flash, but it didn't help. Maybe because of this commit? https://github.com/bluekitchen/btstack/commit/a71df68ad195a359a83f8b5163e365003a7bd0d8

`CC build/bootloader_support/src/secure_boot_signatures.o In file included from /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:22:0: /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c: In function 'esp_secure_boot_verify_signature_block': /home/chainer/esp/esp-idf/components/btstack/3rd-party/micro-ecc/uECC.h:42:24: error: called object is not a function or function pointer

define uECC_secp256r1 3

                    ^

/home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:93:33: note: in expansion of macro 'uECC_secp256r1' uECC_secp256r1()); ^ /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:38:20: warning: passing argument 3 of 'uECC_verify' makes pointer from integer without a cast [-Wint-conversion]

define DIGEST_LEN 32

                ^

/home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:91:33: note: in expansion of macro 'DIGEST_LEN' DIGEST_LEN, ^ In file included from /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:22:0: /home/chainer/esp/esp-idf/components/btstack/3rd-party/micro-ecc/uECC.h:236:5: note: expected 'const uint8_t {aka const unsigned char }' but argument is of type 'int' int uECC_verify(const uint8_t public_key[uECC_BYTES2], ^ /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:89:16: error: too many arguments to function 'uECC_verify' is_valid = uECC_verify(signature_verification_key_start, ^ In file included from /home/chainer/esp/esp-idf/components/bootloader_support/src/secure_boot_signatures.c:22:0: /home/chainer/esp/esp-idf/components/btstack/3rd-party/micro-ecc/uECC.h:236:5: note: declared here int uECC_verify(const uint8_t public_key[uECC_BYTES2], ^ make[1]: [/home/chainer/esp/esp-idf/make/component_wrapper.mk:290: src/secure_boot_signatures.o] Error 1 make: [/home/chainer/esp/esp-idf/make/project.mk:578: component-bootloader_support-build] Error 2`

mringwal commented 5 years ago

That's most likely related to the a71df68. What version (git commit) of esp-idf do you use? I did use the latest version from their master when making this commit.

fluffymadness commented 5 years ago

ah ok...will update esp-idf then and try again.

fluffymadness commented 5 years ago

Thx, works fine now. Here is the non-terminating sdptool request log for the keyboard example. sdptool.zip

fluffymadness commented 5 years ago

I made a small pull request for a working hid-gamepad example. Your last fix got it to work in windows 10 too.

mringwal commented 5 years ago

Thanks for the sdptool log. In it, we see bluez creating an SDP connection and requesting the SDP record for handle X, with X = 0x10000, 0x10001, 0x10002, ...

The SDP Record Handle is a 32-bit number, asking one by one starting at 0x10000 is pretty odd. BTstack responds for 0x10001 - which is the HID SDP record and 'invalid handle' otherwise.

Usually, an SDP client ask for 'give me the record handles for all records that match X', or, 'give me the following properties for all records that macht X'. I'll close the ticket: HID is working, no idea about the SDP query.