Merging HFP and HID into a device

[Chan Danny]

Hi Matthias,

I am using ESP32 with BTStack. I want to combine the HFP and HID into my device, I simply merge the setup and packet_handler parts of the hfp and hid demo examples (modified the hid such that no password authentication)

When I run the problem, I can pair up the hid and hfp. Initially, hid is working but audio fails with errors "Audio connection establishment failed with status 0x12", "Audio connection establishment failed with status 0x1d". Then I restart my device, then the "HCI_EVENT_DISCONNECTION_COMPLETE" event trigger repeatedly (Later I trace the error is SM_EVENT_IDENTITY_RESOLVING_FAILED). Later somehow I can connect audio, but hid is not working.

So is it possible to have hfp and hid working at the same time?

If yes, how can make it? What are the reasons of audio error and disconnect error?

Thank you so much in advance. 

The following is the setup code, I can provide information if needed.

void merge_setup()

{

    sco_demo_init();

l2cap_init();

// Classic HFP 

    uint16_t hf_supported_features =

        (1 << HFP_HFSF_ESCO_S4) |

        (1 << HFP_HFSF_CLI_PRESENTATION_CAPABILITY) |

        (1 << HFP_HFSF_HF_INDICATORS) |

        (1 << HFP_HFSF_CODEC_NEGOTIATION) |

        (1 << HFP_HFSF_ENHANCED_CALL_STATUS) |

        (1 << HFP_HFSF_REMOTE_VOLUME_CONTROL);

    int wide_band_speech = 1;

    rfcomm_init();

    hfp_hf_init(rfcomm_channel_nr);

    hfp_hf_init_supported_features(hf_supported_features);

    hfp_hf_init_hf_indicators(sizeof(indicators) / sizeof(uint16_t), indicators);

    hfp_hf_init_codecs(sizeof(codecs), codecs);

    sdp_init();

    memset(hfp_service_buffer, 0, sizeof(hfp_service_buffer));

    hfp_hf_create_sdp_record(hfp_service_buffer, 0x10001, rfcomm_channel_nr, hfp_hf_service_name, hf_supported_features, wide_band_speech);

    printf("SDP service record size: %u\n", de_get_len(hfp_service_buffer));

    sdp_register_service(hfp_service_buffer);

#ifdef ENABLE_GATT_OVER_CLASSIC

    // init SDP, create record for GATT and register with SDP

    memset(gatt_service_buffer, 0, sizeof(gatt_service_buffer));

    gatt_create_sdp_record(gatt_service_buffer, 0x10001, ATT_SERVICE_GATT_SERVICE_START_HANDLE, ATT_SERVICE_GATT_SERVICE_END_HANDLE);

    sdp_register_service(gatt_service_buffer);

    printf("SDP service record size: %u\n", de_get_len(gatt_service_buffer));

#endif

    gap_discoverable_control(1);

    gap_set_class_of_device(0x200408);

    gap_set_local_name("HFP HF Demo 00:00:00:00:00:00");

    // register for HCI events and SCO packets

    hci_event_callback_registration.callback = &packet_handler;

    hci_add_event_handler(&hci_event_callback_registration);

    hci_register_sco_packet_handler(&packet_handler);

    // register for HFP events

    hfp_hf_register_packet_handler(packet_handler);

#ifdef HAVE_BTSTACK_STDIN

    // parse human readable Bluetooth address

    sscanf_bd_addr(device_addr_string, device_addr);

    btstack_stdin_setup(stdin_process);

#endif

// BLE HID

    // setup le device db

    le_device_db_init();

    // setup SM: Display only

    sm_init();

sm_set_secure_connections_only_mode(true);

/*

sm_set_io_capabilities(IO_CAPABILITY_DISPLAY_YES_NO);

    sm_set_authentication_requirements(SM_AUTHREQ_SECURE_CONNECTION);

    sm_set_io_capabilities(IO_CAPABILITY_DISPLAY_ONLY);

    sm_set_authentication_requirements(SM_AUTHREQ_SECURE_CONNECTION | SM_AUTHREQ_BONDING);

*/

    // setup ATT server

    att_server_init(profile_data, NULL, NULL);

    // setup battery service

    battery_service_server_init(battery);

    // setup device information service

    device_information_service_server_init();

    // setup HID Device service

    hids_device_init(0, hid_descriptor_keyboard_boot_mode, sizeof(hid_descriptor_keyboard_boot_mode));

    // setup advertisements

    uint16_t adv_int_min = 0x0030;

    uint16_t adv_int_max = 0x0030;

    uint8_t adv_type = 0;

    bd_addr_t null_addr;

    memset(null_addr, 0, 6);

    gap_advertisements_set_params(adv_int_min, adv_int_max, adv_type, 0, null_addr, 0x07, 0x00);

    gap_advertisements_set_data(adv_data_len, (uint8_t*) adv_data);

    gap_advertisements_enable(1);

    // register for SM events

    sm_event_callback_registration.callback = &packet_handler;

    sm_add_event_handler(&sm_event_callback_registration);

    // register for HIDS

    hids_device_register_packet_handler(packet_handler);

// handling swithc and keys

touch_switch_task_init(); 

}

/* @section Main Application Setup

 *

 * @text Listing MainConfiguration shows main application code. 

 * To run a HFP HF service you need to initialize the SDP, and to create and register HFP HF record with it. 

 * The packet_handler is used for sending commands to the HFP AG. It also receives the HFP AG's answers.

 * The stdin_process callback allows for sending commands to the HFP AG. 

 * At the end the Bluetooth stack is started.

 */

/* LISTING_START(MainConfiguration): Setup HFP Hands-Free unit */

int btstack_main(int argc, const char *argv[]);

int btstack_main(int argc, const char *argv[])

{

    (void)argc;

    (void)argv;

merge_setup();

    // turn on!

    hci_power_control(HCI_POWER_ON);

    return 0;

}

Best Regards,

Danny 

[Chan Danny]

Hi Matthias,

I managed to fix the Disconnect issue, but still have the following problems:

1. Seems they cannot work together, if I connect to hid, then my keypad work, but cannot connect audio (Audio connection establishment failed with status 0x12, Audio connection establishment failed with status 0x1d). If I do the other way, when audio can connect, keypad not work, I need to remove both device and reset.

2. Voice quality is worse than just hfp profile only (no hid profile added in the code)

I run out of ideas, do you have any ideas to the problems? I need some help.... Thanks

Is it possible to have hfp and hid (BLE) work together actually?

Thanks!

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

There are no obvious reasons why you shouldn't be able to use HFP and HID-over-GATT (HIDS) at the same time. HFP is very sensible and having an additional LE connection might reduce HFP quality.
Is HID and HFP used with the same device? I would suggest then to use HID and Classic HID as this won't degrade HFP quality.

To debug the audio connection errors, I would suggest to start with the HFP only demo and enable HCI packet logging, then convert the log into .pklg for analysis.
Then, add e.g. the LE advertisements and try again, plus compare logs. Then, add HIDS and repeat.

You can also try on a desktop system with an USB Bluetooth dongle - that's easier for testing and that provides the HCI packet log automatically.

Best
Matthias

> --
> You received this message because you are subscribed to the Google Groups "btstack-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to btstack-dev...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/2eb65bad-489c-48ad-8d1a-2563f81facb4n%40googlegroups.com.

[Chan Danny]

Hi Matthias,

Thanks for your reply!

I also think of trying Classic HID, I compiled the Classic HID example and it also requires authentication during pairing. How to remove the authentication as it is different in BLE?

Secondly, I added hci_dump_init(hci_dump_embedded_stdout_get_instance()) for enabling of logs, but has linker error: undefined reference to `hci_dump_embedded_stdout_get_instance'

It may be obvious question, but I have less experience on btstack and cannot figure it out, do you know why?

Thanks again.

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

I don't understand. What's the problem with pairing in Classic? The same pairing is used for HFP and HID (so that's even better).

If you get a link error for hci_dump_embedded_stdout_get_instance, you probably have an older copy of the stack in the esp-idf tree. Please re-run ./integrate_btstack.py and try again

best
matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/5d94cd01-658b-4a2f-8238-b3d8fc4b0650n%40googlegroups.com.

[Chan Danny]

Hi Matthias,

Thanks for your reply!

When I run the program, it can pair but not connected. When I type something in the console, it will try to connect but fail, (Connection fail, status 0x4). Please see picture below?

After I re-run the integrate_btstack.py, I still cannot link, do you know why?

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

Error 0x04 is Page Timeout: it means it didn't not find the device with that address. does the address in the log output match your Windows PC?

As for the link error: please get a clean copy of btstack and run integrate_btstack.py. Then verify that you have a esp-idf/components/btstack/platform/embedded/hci_dump_embedded_stdout.c
It should then compile.

If possible, please post logs either as text or attache a text file.

Cheers
Mathias

> On 30 Aug 2021, at 20:59, Chan Danny <dannychan...@gmail.com> wrote:
>
> Hi Matthias,
>
> Thanks for your reply!
>

> When I run the program, it can pair but not connected. When I type something in the console, it will try to connect but fail, (Connection fail, status 0x4). Please see picture below?
>

> <hid_keyboard.jpg>
>
> After I re-run the integrate_btstack.py, I still cannot link, do you know why?
>

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/abf353fc-198b-4a6c-844f-02ade757b4ban%40googlegroups.com.
> <hid_keyboard.jpg><link error.jpg>

[Chan Danny]

Dear Mathias,

Thanks for your reply!

Just check the BT address of my PC, it really not the same as the one in the log! Oh, do you know the reason?

I have downloaded btstack-master again from github and I can find esp-idf/components/btstack/platform/embedded/hci_dump_embedded_stdout.c

I run integrate_btstack.py but still have that link error. I think it didn't compile hci_dump_embedded_stdout.c, in fact do I need to configure something eg. menuconfig or others?

Best Regards,

Danny 

[Chan Danny]

Hi Mathias,

For the hid_keyboard_demo in my device, if it use with my Android phone, it is perfect, able to pair and connect automatically, and re-connect if device is reset. However, I tried 3 PCs (Windows 10), two PCs can just pair but cannot connect, somehow if connected, will be disconnected itself after a few seconds, the third one can connect and will not disconnect itself, but after device reset, it will not re-connect and need to remove device to start again. I wonder is there any things I missed out when using with Windows?

By the way, I have downloaded btstack-master again from github and I can find esp-idf/components/btstack/platform/embedded/hci_dump_embedded_stdout.c

I run integrate_btstack.py but still have that link error. I think it DIDN'T compile hci_dump_embedded_stdout.c, in fact do I need to configure something eg. menuconfig or others, or not master branch?

Thanks!

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

There's an issue with the HID keyboard demo from the master branch in Windows, where typing is "slow" (about 1 character per second on my system) and which has been fixed on the develop branch. I haven't seen any connection problems.

I don't know why it doesn't compile for you. Please verify that your project uses the same esp-idf installation where the integrate_bttstack.py script has copied the sources. A simple trick is to modify (e.g. add a #error line) to a file that seems to get compiled. If the build fails, it was the correct file. If not, it compiles a different file/rtree.

As a quick check, I've switched to master, deleted esp-idf/components/btstack, run ./integrate_btstack.py, and run make in the hid_keyboard_demo. Please compare your compile output to the attached file.

Cheers
Matthias

[Chan Danny]

Dear Matthias,

I finally can compile the program with hci dump log. I need to download the develop branch and run ./integrate_btstack.py again.

Because the following is essential in the develop branch:

# add hci dump stdout

shutil.copy(local_dir+'/../../platform/embedded/hci_dump_embedded_stdout.c', IDF_BTSTACK)

However, when I run the program with hci dump log, I cannot pair, is it because the logs with make the program runs slowly? I attached a log for reference.

Logs:

Admin@LAPTOP-N9NDF2CL MINGW32 ~/esp/hid_keyboard_demo

$ make monitor

Toolchain path: /c/Users/Admin/.espressif/tools/xtensa-esp32-elf/esp-2021r1-8.4.0/xtensa-esp32-elf/bin/xtensa-esp32-elf-gcc

Toolchain version: esp-2021r1

Compiler version: 8.4.0

Python requirements from C:/msys32/home/Admin/esp/esp-idf/requirements.txt are satisfied.

MONITOR

←[0;33m--- WARNING: GDB cannot open serial ports accessed as COMx←[0m

←[0;33m--- Using \\.\COM6 instead...←[0m

--- idf_monitor on \\.\COM6 115200 ---

--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

configsip: 188777542, 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:0x3fff0030,len:5588

load:0x40078000,len:13776

ho 0 tail 12 room 4

load:0x40080400,len:3248

entry 0x4008060c

I (215) cpu_start: Pro cpu up.

I (215) cpu_start: Single core mode

I (223) cpu_start: Pro cpu start user code

I (223) cpu_start: cpu freq: 240000000

I (223) cpu_start: Application information:

I (228) cpu_start: Project name:     hid_keyboard_demo

I (233) cpu_start: App version:      1

I (238) cpu_start: Compile time:     Sep  3 2021 21:38:45

I (244) cpu_start: ELF file SHA256:  ca946de60a48a2ba...

I (250) cpu_start: ESP-IDF:          v4.4-dev-2594-ga20df743f1-dirty

I (257) heap_init: Initializing. RAM available for dynamic allocation:

I (264) heap_init: At 3FF80000 len 00002000 (8 KiB): RTCRAM

I (270) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

I (276) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM

I (283) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

I (289) heap_init: At 3FFCA0F0 len 00015F10 (87 KiB): DRAM

I (295) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM

I (301) heap_init: At 40078000 len 00008000 (32 KiB): IRAM

I (307) heap_init: At 40096E3C len 000091C4 (36 KiB): IRAM

I (315) spi_flash: detected chip: gd

I (318) spi_flash: flash io: dio

I (322) sleep: Configure to isolate all GPIO pins in sleep state

I (329) sleep: Enable automatic switching of GPIO sleep configuration

I (336) esp_core_dump_uart: Init core dump to UART

I (341) cpu_start: Starting scheduler on PRO CPU.

[00:00:00.363] LOG -- l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535

HID service record size: 274

Device ID SDP service record size: 64

[00:00:00.367] LOG -- l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x13 mtu 100

[00:00:00.374] LOG -- l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x11 mtu 100

[00:00:00.382] LOG -- hci.c.3960: hci_power_control: 1, current mode 0

[00:00:00.387] LOG -- main.c.209: transport_init

[00:00:00.391] LOG -- main.c.225: transport_open

I (396) BTDM_INIT: BT controller compile version [bfbbe1e]

I (402) system_api: Base MAC address is not set

I (407) system_api: read default base MAC address from EFUSE

I (416) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

[00:00:00.811] LOG -- hci.c.5428: BTSTACK_EVENT_STATE 1

[00:00:00.811] EVT <= 60 01 01

[00:00:00.812] CMD => 03 0C 00

[00:00:00.812] EVT <= 6E 00

[00:00:00.816] EVT <= 0E 04 05 03 0C 00

[00:00:00.817] CMD => 01 10 00

[00:00:00.823] EVT <= 0E 0C 05 01 10 00 08 0E 03 08 60 00 0E 03

[00:00:00.826] LOG -- hci.c.2232: Manufacturer: 0x0060

[00:00:00.831] EVT <= 6E 00

[00:00:00.833] CMD => 14 0C 00

[00:00:00.838] 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.904] LOG -- hci.c.2138: local name:

[00:00:00.909] LOG -- hci.c.1810: Received local name, need baud change 0

[00:00:00.915] EVT <= 6E 00

[00:00:00.918] CMD => 02 10 00

[00:00:00.923] 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.941] LOG -- hci.c.2250: Local supported commands summary bf - 1f

[00:00:00.948] EVT <= 6E 00

[00:00:00.950] CMD => 09 10 00

[00:00:00.955] EVT <= 0E 0A 05 09 10 00 E2 85 D0 AC CD 98

[00:00:00.958] LOG -- hci.c.2193: Local Address, Status: 0x00: Addr: 98:CD:AC:D0:85:E2

[00:00:00.966] EVT <= 6E 00

[00:00:00.968] CMD => 05 10 00

[00:00:00.974] EVT <= 0E 0B 05 05 10 00 FD 03 FF 09 00 04 00

[00:00:00.977] LOG -- hci.c.2155: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4

[00:00:00.988] EVT <= 6E 00

[00:00:00.990] CMD => 03 10 00

[00:00:00.995] EVT <= 0E 0C 05 03 10 00 BF EE CD FE DB FF 7B 87

[00:00:00.999] LOG -- hci.c.2218: Packet types cc18, eSCO 1

[00:00:01.004] LOG -- hci.c.2221: BR/EDR support 1, LE support 1

[00:00:01.010] EVT <= 6E 00

[00:00:01.012] CMD => 33 0C 07 00 04 3C 14 00 0A 00

[00:00:01.020] EVT <= 0E 04 05 33 0C 00

[00:00:01.021] EVT <= 6E 00

[00:00:01.023] CMD => 31 0C 01 03

[00:00:01.029] EVT <= 0E 04 05 31 0C 00

[00:00:01.030] EVT <= 6E 00

[00:00:01.033] CMD => 01 0C 08 FF FF FF FF FF FF FF 3F

[00:00:01.040] EVT <= 0E 04 05 01 0C 00

[00:00:01.041] EVT <= 6E 00

[00:00:01.044] CMD => 56 0C 01 01

[00:00:01.049] EVT <= 0E 04 05 56 0C 00

[00:00:01.051] EVT <= 6E 00

[00:00:01.053] CMD => 18 0C 02 00 60

[00:00:01.059] EVT <= 0E 04 05 18 0C 00

[00:00:01.060] EVT <= 6E 00

[00:00:01.063] CMD => 0F 08 02 05 00

[00:00:01.068] EVT <= 0E 04 05 0F 08 00

[00:00:01.070] EVT <= 6E 00

[00:00:01.072] CMD => 24 0C 03 40 25 00

[00:00:01.078] EVT <= 0E 04 05 24 0C 00

[00:00:01.080] EVT <= 6E 00

[00:00:01.082] CMD => 13 0C F8 48 49 44 20 4B 65 79 62 6F 61 72 64 20 44 65 6D 6F 20 39 38 3A 43 44 3A 41 43 3A 44 30 3A 38 35 3A 45 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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.152] EVT <= 0E 04 05 13 0C 00

[00:00:01.153] EVT <= 6E 00

[00:00:01.156] 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 39 38 3A 43 44 3A 41 43 3A 44 30 3A 38 35 3A 45 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 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.224] EVT <= 0E 04 05 52 0C 00

[00:00:01.225] EVT <= 6E 00

[00:00:01.228] CMD => 45 0C 01 00

[00:00:01.233] EVT <= 0E 04 05 45 0C 00

[00:00:01.235] EVT <= 6E 00

[00:00:01.237] CMD => 7A 0C 01 01

[00:00:01.243] EVT <= 0E 04 05 7A 0C 00

[00:00:01.244] EVT <= 6E 00

[00:00:01.247] CMD => 1A 0C 01 03

[00:00:01.252] EVT <= 0E 04 05 1A 0C 00

[00:00:01.253] LOG -- hci.c.5554: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1

[00:00:01.259] EVT <= 66 01 01

[00:00:01.263] EVT <= 6E 00

[00:00:01.265] CMD => 2F 0C 01 01

[00:00:01.271] EVT <= 0E 04 05 2F 0C 00

[00:00:01.272] EVT <= 6E 00

[00:00:01.274] CMD => 5B 0C 01 01

[00:00:01.280] EVT <= 0E 04 05 5B 0C 00

[00:00:01.281] EVT <= 6E 00

[00:00:01.284] CMD => 02 20 00

[00:00:01.289] EVT <= 0E 07 05 02 20 00 FB 00 0A

[00:00:01.291] LOG -- hci.c.2175: hci_le_read_buffer_size: size 251, count 10

[00:00:01.298] EVT <= 6E 00

[00:00:01.301] CMD => 6D 0C 02 01 00

[00:00:01.306] EVT <= 0E 04 05 6D 0C 00

[00:00:01.308] LOG -- hci.c.1918: Supported commands 30

[00:00:01.313] EVT <= 6E 00

[00:00:01.315] CMD => 01 20 08 FF 09 08 00 00 00 00 00

[00:00:01.323] EVT <= 0E 04 05 01 20 00

[00:00:01.324] EVT <= 6E 00

[00:00:01.326] CMD => 2F 20 00

[00:00:01.331] EVT <= 0E 0C 05 2F 20 00 FB 00 48 08 FB 00 48 08

[00:00:01.335] LOG -- hci.c.2182: hci_le_read_maximum_data_length: tx octets 251, tx time 2120 us

[00:00:01.344] EVT <= 6E 00

[00:00:01.346] CMD => 24 20 04 FB 00 48 08

[00:00:01.353] EVT <= 0E 04 05 24 20 00

[00:00:01.354] EVT <= 6E 00

[00:00:01.356] CMD => 0F 20 00

[00:00:01.361] EVT <= 0E 05 05 0F 20 00 0C

[00:00:01.363] LOG -- hci.c.2188: hci_le_read_white_list_size: size 12

[00:00:01.369] EVT <= 6E 00

[00:00:01.372] CMD => 0B 20 07 01 E0 01 30 00 00 00

[00:00:01.379] EVT <= 0E 04 05 0B 20 00

[00:00:01.380] LOG -- hci.c.1668: hci_init_done -> HCI_STATE_WORKING

[00:00:01.386] LOG -- hci.c.5428: BTSTACK_EVENT_STATE 2

[00:00:01.391] EVT <= 60 01 02

[00:00:01.394] LOG -- main.c.346: transport: configure SCO over HCI, result 0x0000

BTstack up and running at 98:CD:AC:D0:85:E2

[00:00:01.405] EVT <= 6E 00

[00:00:27.553] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 01

[00:00:27.554] LOG -- hci.c.2594: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

[00:00:27.555] LOG -- hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fd

[00:00:27.563] LOG -- hci.c.4595: sending hci_accept_connection_request

[00:00:27.569] CMD => 09 04 07 B1 E3 69 B5 1B 1C 01

[00:00:27.574] EVT <= 0F 04 00 05 09 04

[00:00:27.578] EVT <= 6E 00

[00:00:27.766] EVT <= 03 0B 00 80 00 B1 E3 69 B5 1B 1C 01 00

[00:00:27.767] LOG -- hci.c.2618: Connection_complete (status=0) 1C:1B:B5:69:E3:B1

[00:00:27.768] LOG -- hci.c.2638: New connection: handle 128, 1C:1B:B5:69:E3:B1

[00:00:27.775] LOG -- hci.c.5497: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

[00:00:27.782] EVT <= 61 01 01

[00:00:27.785] CMD => 1B 04 02 80 00

[00:00:27.788] EVT <= 1B 03 80 00 05

[00:00:27.791] ACL <= 80 20 0C 00 08 00 01 00 02 13 04 00 01 00 40 00

[00:00:27.798] LOG -- l2cap.c.2012: create channel 0x3ffd2ca4, local_cid 0x0041

[00:00:27.805] LOG -- l2cap.c.1090: L2CAP_EVENT_INCOMING_CONNECTION addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40

[00:00:27.817] EVT <= 72 0E B1 E3 69 B5 1B 1C 80 00 01 00 41 00 40 00

[00:00:27.823] LOG -- l2cap.c.2660: L2CAP_ACCEPT_CONNECTION local_cid 0x41

[00:00:27.830] EVT <= 0F 04 00 05 1B 04

[00:00:27.833] EVT <= 0B 0B 00 80 00 FF FE 0F FE DB FF 7B 87

[00:00:27.839] EVT <= 6E 00

[00:00:27.842] ACL => 80 00 10 00 0C 00 01 00 03 13 08 00 41 00 40 00 00 00 00 00

[00:00:27.849] EVT <= 6E 00

[00:00:27.851] ACL => 80 00 10 00 0C 00 01 00 04 01 08 00 40 00 00 00 01 02 9B 06

[00:00:27.859] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

[00:00:27.865] LOG -- l2cap.c.1259: l2cap_start_rtx for local cid 0x41

[00:00:27.871] EVT <= 13 05 01 80 00 01 00

[00:00:27.875] EVT <= 13 05 01 80 00 01 00

[00:00:27.879] ACL <= 80 20 10 00 0C 00 01 00 04 14 08 00 41 00 00 00 01 02 00 04

[00:00:27.886] LOG -- l2cap.c.2871: L2CAP signaling handler code 4, state 11

[00:00:27.893] LOG -- l2cap.c.2716: Remote MTU 1024

[00:00:27.898] ACL <= 80 20 12 00 0E 00 01 00 05 01 0A 00 41 00 00 00 00 00 01 02 00 04

[00:00:27.905] LOG -- l2cap.c.2871: L2CAP signaling handler code 5, state 11

[00:00:27.912] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

[00:00:27.918] LOG -- l2cap.c.2801: l2cap_signaling_handle_configure_response

[00:00:27.925] EVT <= 6E 00

[00:00:27.928] ACL => 80 00 12 00 0E 00 01 00 05 14 0A 00 40 00 00 00 00 00 01 02 00 04

[00:00:27.936] LOG -- l2cap.c.1056: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0

[00:00:27.953] EVT <= 70 18 00 B1 E3 69 B5 1B 1C 80 00 01 00 41 00 40 00 9B 06 00 04 00 00 01 00 00

[00:00:27.962] EVT <= 13 05 01 80 00 01 00

[00:00:27.966] EVT <= 32 09 B1 E3 69 B5 1B 1C 01 00 05

[00:00:27.971] LOG -- hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

[00:00:27.978] EVT <= DF 0A 80 00 B1 E3 69 B5 1B 1C 01 00

[00:00:27.983] EVT <= 31 06 B1 E3 69 B5 1B 1C

[00:00:27.988] EVT <= 6E 00

[00:00:27.990] CMD => 35 0C 05 01 80 00 03 00

[00:00:27.994] EVT <= 6E 00

[00:00:27.997] LOG -- hci.c.5643: gap_mitm_protection_required_for_security_level 2

[00:00:28.004] CMD => 2B 04 09 B1 E3 69 B5 1B 1C 03 00 04

[00:00:28.010] EVT <= 0E 0A 05 2B 04 00 B1 E3 69 B5 1B 1C

[00:00:28.015] EVT <= 6E 00

[00:00:28.017] CMD => 1C 04 03 80 00 01

[00:00:28.021] EVT <= 6E 00

[00:00:28.295] EVT <= 33 0A B1 E3 69 B5 1B 1C 80 EB 08 00

[00:00:28.295] LOG -- hid_keyboard_demo.c.332: SSP User Confirmation Request with numeric value '584576'

[00:00:28.299] LOG -- hid_keyboard_demo.c.333: SSP User Confirmation Auto accept

[00:00:58.295] EVT <= 36 07 22 B1 E3 69 B5 1B 1C

[00:00:58.295] LOG -- hci.c.429: pairing complete, status 22

[00:00:58.296] EVT <= E0 09 80 00 B1 E3 69 B5 1B 1C 22 3F

[00:00:58.299] EVT <= 0F 04 02 05 1C 04

[00:00:58.303] CMD => 2C 04 06 B1 E3 69 B5 1B 1C

E(25, 0) in user_cfm_req_reply

[00:00:58.310] EVT <= 0E 0A 05 2C 04 0C B1 E3 69 B5 1B 1C

[00:00:58.315] EVT <= 6E 00

[00:00:58.387] EVT <= 05 04 00 80 00 22

[00:00:58.388] LOG -- l2cap.c.1084: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41

[00:00:58.388] EVT <= 71 02 41 00

[00:00:58.390] LOG -- l2cap.c.2018: free channel 0x3ffd2ca4, local_cid 0x0041

[00:00:58.397] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

[00:00:58.403] LOG -- hci.c.1014: Connection closed: handle 0x80, 1C:1B:B5:69:E3:B1

[00:00:58.410] LOG -- hci.c.5497: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0

[00:00:58.417] EVT <= 61 01 00

[00:01:32.230] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 01

[00:01:32.231] LOG -- hci.c.2594: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

[00:01:32.232] LOG -- hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fd

[00:01:32.240] LOG -- hci.c.4595: sending hci_accept_connection_request

[00:01:32.246] CMD => 09 04 07 B1 E3 69 B5 1B 1C 01

[00:01:32.251] EVT <= 0F 04 00 05 09 04

[00:01:32.254] EVT <= 6E 00

[00:01:32.455] EVT <= 03 0B 00 81 00 B1 E3 69 B5 1B 1C 01 00

[00:01:32.456] LOG -- hci.c.2618: Connection_complete (status=0) 1C:1B:B5:69:E3:B1

[00:01:32.457] LOG -- hci.c.2638: New connection: handle 129, 1C:1B:B5:69:E3:B1

[00:01:32.464] LOG -- hci.c.5497: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

[00:01:32.470] EVT <= 61 01 01

[00:01:32.474] CMD => 1B 04 02 81 00

[00:01:32.477] EVT <= 1B 03 81 00 05

[00:01:32.480] ACL <= 81 20 0C 00 08 00 01 00 02 16 04 00 01 00 40 00

[00:01:32.487] LOG -- l2cap.c.2012: create channel 0x3ffd2ca4, local_cid 0x0042

[00:01:32.493] LOG -- l2cap.c.1090: L2CAP_EVENT_INCOMING_CONNECTION addr 1C:1B:B5:69:E3:B1 handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x40

[00:01:32.506] EVT <= 72 0E B1 E3 69 B5 1B 1C 81 00 01 00 42 00 40 00

[00:01:32.512] LOG -- l2cap.c.2660: L2CAP_ACCEPT_CONNECTION local_cid 0x42

[00:01:32.519] EVT <= 0F 04 00 05 1B 04

[00:01:32.522] EVT <= 0B 0B 00 81 00 FF FE 0F FE DB FF 7B 87

[00:01:32.528] EVT <= 6E 00

[00:01:32.530] ACL => 81 00 10 00 0C 00 01 00 03 16 08 00 42 00 40 00 00 00 00 00

[00:01:32.538] EVT <= 6E 00

[00:01:32.540] ACL => 81 00 10 00 0C 00 01 00 04 02 08 00 40 00 00 00 01 02 9B 06

[00:01:32.548] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x42

[00:01:32.554] LOG -- l2cap.c.1259: l2cap_start_rtx for local cid 0x42

[00:01:32.560] EVT <= 13 05 01 81 00 01 00

[00:01:32.564] EVT <= 6E 00

[00:01:32.567] CMD => 35 0C 05 01 81 00 01 00

[00:01:32.571] EVT <= 6E 00

[00:01:32.573] CMD => 1C 04 03 81 00 01

[00:01:32.577] EVT <= 0F 04 00 05 1C 04

[00:01:32.581] EVT <= 6E 00

[00:01:32.597] ACL <= 81 20 10 00 0C 00 01 00 04 17 08 00 42 00 00 00 01 02 00 04

[00:01:32.598] LOG -- l2cap.c.2871: L2CAP signaling handler code 4, state 11

[00:01:32.601] LOG -- l2cap.c.2716: Remote MTU 1024

[00:01:32.606] ACL => 81 00 12 00 0E 00 01 00 05 17 0A 00 40 00 00 00 00 00 01 02 00 04

[00:01:32.614] EVT <= 13 05 01 81 00 01 00

[00:01:32.617] ACL <= 81 20 12 00 0E 00 01 00 05 02 0A 00 42 00 00 00 00 00 01 02 00 04

[00:01:32.625] LOG -- l2cap.c.2871: L2CAP signaling handler code 5, state 11

[00:01:32.632] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x42

[00:01:32.638] LOG -- l2cap.c.2801: l2cap_signaling_handle_configure_response

[00:01:32.645] LOG -- l2cap.c.1056: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 1C:1B:B5:69:E3:B1 handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0

[00:01:32.662] EVT <= 70 18 00 B1 E3 69 B5 1B 1C 81 00 01 00 42 00 40 00 9B 06 00 04 00 00 01 00 00

[00:01:32.671] EVT <= 23 0D 00 81 00 01 02 0F 00 00 00 00 00 00 00

[00:01:32.677] EVT <= 13 05 01 81 00 01 00

[00:01:32.681] EVT <= 32 09 B1 E3 69 B5 1B 1C 01 00 05

[00:01:32.686] LOG -- hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

[00:01:32.693] EVT <= DF 0A 81 00 B1 E3 69 B5 1B 1C 01 00

[00:01:32.699] EVT <= 31 06 B1 E3 69 B5 1B 1C

[00:01:32.703] EVT <= 6E 00

[00:01:32.705] CMD => 35 0C 05 01 81 00 02 00

[00:01:32.710] EVT <= 6E 00

[00:01:32.712] LOG -- hci.c.5643: gap_mitm_protection_required_for_security_level 2

[00:01:32.720] CMD => 2B 04 09 B1 E3 69 B5 1B 1C 03 00 04

[00:01:32.725] EVT <= 0E 0A 05 2B 04 00 B1 E3 69 B5 1B 1C

[00:01:32.730] EVT <= 6E 00

[00:01:32.733] CMD => 1C 04 03 81 00 02

[00:01:32.736] EVT <= 6E 00

[00:01:32.983] EVT <= 33 0A B1 E3 69 B5 1B 1C AA 86 0A 00

[00:01:32.983] LOG -- hid_keyboard_demo.c.332: SSP User Confirmation Request with numeric value '689834'

[00:01:32.986] LOG -- hid_keyboard_demo.c.333: SSP User Confirmation Auto accept

[00:02:02.975] EVT <= 36 07 22 B1 E3 69 B5 1B 1C

[00:02:02.976] LOG -- hci.c.429: pairing complete, status 22

[00:02:02.976] EVT <= E0 09 81 00 B1 E3 69 B5 1B 1C 22 3F

[00:02:02.979] EVT <= 0F 04 02 05 1C 04

[00:02:02.983] CMD => 2C 04 06 B1 E3 69 B5 1B 1C

E(26, 0) in user_cfm_req_reply

[00:02:02.990] EVT <= 0E 0A 05 2C 04 0C B1 E3 69 B5 1B 1C

[00:02:02.995] EVT <= 6E 00

[00:02:03.046] EVT <= 05 04 00 81 00 22

[00:02:03.047] LOG -- l2cap.c.1084: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x42

[00:02:03.047] EVT <= 71 02 42 00

[00:02:03.049] LOG -- l2cap.c.2018: free channel 0x3ffd2ca4, local_cid 0x0042

[00:02:03.056] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x42

[00:02:03.062] LOG -- hci.c.1014: Connection closed: handle 0x81, 1C:1B:B5:69:E3:B1

[00:02:03.069] LOG -- hci.c.5497: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0

[00:02:03.076] EVT <= 61 01 00

Best Regards,

Danny  

[Matthias Ringwald]

Hi Danny

Sorry, forgot about that bit. There's a copy of the file in platform/embedded, but the whole folder isn't included in the build - as some files don't compile.

Back to your issue. The log output slows eveything down, besides audio issues, everything else should still work.
In the log, the stack sends a HCI Read Remote Extended Features Command. Before it gets a response to that, the Controller sends a User Confirmation Request. The stack waits for the Read Read Remote Features Command, which does not arrive, and there's a Link Layer timeout after 30 seconds. Not sure if we can call this a bug in the ESP32 Controller or if there's a work around by the stack.

Did you run the code from develop or from master?

Best
Matthias

> --
> You received this message because you are subscribed to the Google Groups "btstack-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to btstack-dev...@googlegroups.com.

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/3a08f999-9317-4f36-a3fb-f55319d4c205n%40googlegroups.com.

[Chan Danny]

Hi Matthias,

Here are some findings, I hope you have some ideas on how to make hid_keyboard_demo work in Windows.

1. I tried the master and develop branch, no logs added: 

    Master branch: Android working, Windows just pair cannot connect. 

    Develop branch: Both Android and Windows just pair cannot connect.

    

    Master branch is better at least Android is working (But my application has to be used in Windows..............)

2. If logs are added, both Android and Windows under master or develop branch even cannot pair.

3. Somehow can log an occasion that the device just can pair but cannot connect, is there any hints to know why?? 

BTstack up and running at 98:CD:AC:D0:85:E2

[00:00:01.426] EVT <= 6E 00

[00:00:24.975] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 01

[00:00:24.976] LOG -- hci.c.2594: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

[00:00:24.977] LOG -- hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fd

[00:00:24.985] LOG -- hci.c.4595: sending hci_accept_connection_request

[00:00:24.991] CMD => 09 04 07 B1 E3 69 B5 1B 1C 01

[00:00:24.996] EVT <= 0F 04 00 05 09 04

[00:00:24.999] EVT <= 6E 00

[00:00:25.188] EVT <= 03 0B 00 80 00 B1 E3 69 B5 1B 1C 01 00

[00:00:25.188] LOG -- hci.c.2618: Connection_complete (status=0) 1C:1B:B5:69:E3:B1

[00:00:25.190] LOG -- hci.c.2638: New connection: handle 128, 1C:1B:B5:69:E3:B1

[00:00:25.197] LOG -- hci.c.5497: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

[00:00:25.203] EVT <= 61 01 01

[00:00:25.206] CMD => 1B 04 02 80 00

[00:00:25.210] EVT <= 1B 03 80 00 05

[00:00:25.213] EVT <= 0F 04 00 05 1B 04

[00:00:25.217] EVT <= 0B 0B 00 80 00 FF FE 0F FE DB FF 7B 87

[00:00:25.222] EVT <= 6E 00

[00:00:25.225] CMD => 1C 04 03 80 00 01

[00:00:25.228] EVT <= 0F 04 00 05 1C 04

[00:00:25.232] EVT <= 6E 00

[00:00:25.235] EVT <= 23 0D 00 80 00 01 02 0F 00 00 00 00 00 00 00

[00:00:25.241] CMD => 1C 04 03 80 00 02

[00:00:25.244] EVT <= 0F 04 00 05 1C 04

[00:00:25.248] EVT <= 6E 00

[00:00:25.254] ACL <= 80 20 0C 00 08 00 01 00 02 01 04 00 01 00 40 00

[00:00:25.257] LOG -- l2cap.c.2012: create channel 0x3ffd2ca4, local_cid 0x0041

[00:00:25.264] LOG -- l2cap.c.1090: L2CAP_EVENT_INCOMING_CONNECTION addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40

[00:00:25.276] EVT <= 72 0E B1 E3 69 B5 1B 1C 80 00 01 00 41 00 40 00

[00:00:25.282] LOG -- l2cap.c.2660: L2CAP_ACCEPT_CONNECTION local_cid 0x41

[00:00:25.289] ACL => 80 00 10 00 0C 00 01 00 03 01 08 00 41 00 40 00 00 00 00 00

[00:00:25.297] EVT <= 23 0D 00 80 00 02 02 20 0B 00 00 00 00 00 00

[00:00:25.302] LOG -- hci.c.2077: Remote features 03, bonding flags f8

[00:00:25.309] LOG -- l2cap.c.2356: remote supported features, channel 0x3ffd2ca4, cid 0041 - state 11

[00:00:25.318] EVT <= 13 05 01 80 00 01 00

[00:00:25.321] ACL <= 80 20 10 00 0C 00 01 00 04 02 08 00 41 00 00 00 01 02 00 04

[00:00:25.329] LOG -- l2cap.c.2871: L2CAP signaling handler code 4, state 11

[00:00:25.335] LOG -- l2cap.c.2716: Remote MTU 1024

[00:00:25.340] EVT <= 6E 00

[00:00:25.343] ACL => 80 00 12 00 0E 00 01 00 05 02 0A 00 40 00 00 00 00 00 01 02 00 04

[00:00:25.351] EVT <= 6E 00

[00:00:25.353] ACL => 80 00 10 00 0C 00 01 00 04 01 08 00 40 00 00 00 01 02 9B 06

[00:00:25.361] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

[00:00:25.367] LOG -- l2cap.c.1259: l2cap_start_rtx for local cid 0x41

[00:00:25.373] EVT <= 13 05 01 80 00 01 00

[00:00:25.377] EVT <= 13 05 01 80 00 01 00

[00:00:25.381] ACL <= 80 20 12 00 0E 00 01 00 05 01 0A 00 41 00 00 00 00 00 01 02 00 04

[00:00:25.388] LOG -- l2cap.c.2871: L2CAP signaling handler code 5, state 11

[00:00:25.395] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

[00:00:25.401] LOG -- l2cap.c.2801: l2cap_signaling_handle_configure_response

[00:00:25.408] LOG -- l2cap.c.1056: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0

[00:00:25.425] EVT <= 70 18 00 B1 E3 69 B5 1B 1C 80 00 01 00 41 00 40 00 9B 06 00 04 00 00 01 00 00

[00:00:25.434] EVT <= 32 09 B1 E3 69 B5 1B 1C 01 00 05

[00:00:25.439] LOG -- hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

[00:00:25.447] EVT <= DF 0A 80 00 B1 E3 69 B5 1B 1C 01 00

[00:00:25.452] EVT <= 31 06 B1 E3 69 B5 1B 1C

[00:00:25.456] EVT <= 6E 00

[00:00:25.459] CMD => 35 0C 05 01 80 00 03 00

[00:00:25.463] EVT <= 6E 00

[00:00:25.466] LOG -- hci.c.5643: gap_mitm_protection_required_for_security_level 2

[00:00:25.473] CMD => 2B 04 09 B1 E3 69 B5 1B 1C 03 00 04

[00:00:25.479] EVT <= 0E 0A 05 2B 04 00 B1 E3 69 B5 1B 1C

[00:00:25.484] EVT <= 6E 00

[00:00:25.750] EVT <= 33 0A B1 E3 69 B5 1B 1C F0 0C 0A 00

[00:00:25.751] LOG -- hid_keyboard_demo.c.332: SSP User Confirmation Request with numeric value '658672'

[00:00:25.754] LOG -- hid_keyboard_demo.c.333: SSP User Confirmation Auto accept

[00:00:25.762] CMD => 2C 04 06 B1 E3 69 B5 1B 1C

[00:00:25.766] EVT <= 0E 0A 05 2C 04 00 B1 E3 69 B5 1B 1C

[00:00:25.771] EVT <= 6E 00

[00:00:26.069] EVT <= 36 07 00 B1 E3 69 B5 1B 1C

[00:00:26.070] LOG -- hci.c.429: pairing complete, status 00

[00:00:26.070] EVT <= E0 09 80 00 B1 E3 69 B5 1B 1C 00 3F

[00:00:26.083] EVT <= 18 17 B1 E3 69 B5 1B 1C A0 80 30 F3 BA 93 5F 72 EC D8 66 4B 29 74 0D 8E 07

[00:00:26.083] LOG -- hci.c.454: gap_store_link_key_for_bd_addr: 1C:1B:B5:69:E3:B1, type 7

[00:00:26.093] LOG -- btstack_link_key_db_tlv.c.152: tag_for_addr 42544c0e, tag_for_empy 42544c09, tag_for_lowest_seq_nr 42544c0f

[00:00:26.101] LOG -- btstack_link_key_db_tlv.c.166: store with tag 42544c0e

[00:00:26.108] LOG -- btstack_tlv_esp32.c.97: store tag 42544C0E

[00:00:26.116] EVT <= 08 04 00 80 00 02

[00:00:26.118] CMD => 08 14 02 80 00

[00:00:26.121] ACL <= 80 20 18 00 14 00 41 00 06 00 00 00 0F 35 03 19 01 00 03 F8 35 05 0A 00 00 FF FF 00

[00:00:26.131] ACL <= 80 20 0A 00 06 00 01 00 0A 03 02 00 02 00

[00:00:26.136] EVT <= 0E 07 05 08 14 00 80 00 10

[00:00:26.141] LOG -- hci.c.2265: Handle 0080 key Size: 16

[00:00:26.146] LOG -- hci.c.5528: hci_emit_security_level 2 for handle 80

[00:00:26.152] EVT <= D8 03 80 00 02

[00:00:26.155] LOG -- l2cap.c.2376: security level update for handle 0x0080

[00:00:26.162] LOG -- l2cap.c.2386: channel 0x3ffd2ca4, cid 0041 - state 12: actual 2 >= required 0?

[00:00:26.171] EVT <= 6E 00

[00:00:26.174] ACL => 80 00 10 00 0C 00 01 00 0B 03 08 00 02 00 00 00 80 02 00 00

[00:00:26.181] EVT <= 6E 00

[00:00:26.183] EVT <= 78 02 41 00

[00:00:26.187] ACL => 80 00 21 01 1D 01 40 00 07 00 00 01 18 01 15 36 01 12 36 01 0F 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 01 09 02 06 36 00 4A 36 00 47 08 22 25 43 05 01 09 06 A1 01 85 01 05 07 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 0C 09 0C 80 09 02 0D

 28 01 09 02 0E 28 00 09 02 0F 09 06 40 09 02 10 09 0C 80 00

[00:00:26.265] EVT <= 6E 00

[00:00:26.268] CMD => 35 0C 05 01 80 00 02 00

[00:00:26.272] EVT <= 6E 00

[00:00:26.929] EVT <= 13 05 01 80 00 01 00

[00:00:26.937] EVT <= 13 05 01 80 00 01 00

[00:00:26.945] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 01

[00:00:26.946] LOG -- hci.c.2594: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

[00:00:26.947] LOG -- hci.c.4595: sending hci_accept_connection_request

[00:00:26.953] CMD => 09 04 07 B1 E3 69 B5 1B 1C 01

[00:00:26.958] EVT <= 0F 04 0C 05 09 04

[00:00:26.961] EVT <= 6E 00

[00:00:32.075] EVT <= 03 0B 10 81 00 B1 E3 69 B5 1B 1C 01 00

[00:00:32.076] LOG -- hci.c.2618: Connection_complete (status=16) 1C:1B:B5:69:E3:B1

[00:00:32.078] LOG -- hci.c.2012: Outgoing connection to 1C:1B:B5:69:E3:B1 failed

[00:00:52.093] EVT <= 05 04 00 80 00 08

[00:00:52.094] LOG -- l2cap.c.1084: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41

[00:00:52.094] EVT <= 71 02 41 00

[00:00:52.096] LOG -- l2cap.c.2018: free channel 0x3ffd2ca4, local_cid 0x0041

[00:00:52.103] LOG -- l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

4. Android working log:

BTstack up and running at 98:CD:AC:D0:85:E2

[00:00:01.414] EVT <= 6E 00

[00:00:30.086] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 01

[00:00:30.087] LOG -- hci.c.2566: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

[00:00:30.088] LOG -- hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fd

[00:00:30.096] LOG -- hci.c.4504: sending hci_accept_connection_request

[00:00:30.102] CMD => 09 04 07 B1 E3 69 B5 1B 1C 01

[00:00:30.107] EVT <= 0F 04 00 05 09 04

[00:00:30.110] EVT <= 6E 00

[00:00:30.282] EVT <= 03 0B 00 80 00 B1 E3 69 B5 1B 1C 01 00

[00:00:30.283] LOG -- hci.c.2590: Connection_complete (status=0) 1C:1B:B5:69:E3:B1

[00:00:30.284] LOG -- hci.c.2610: New connection: handle 128, 1C:1B:B5:69:E3:B1

[00:00:30.291] LOG -- hci.c.5405: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

[00:00:30.298] EVT <= 61 01 01

[00:00:30.301] CMD => 1B 04 02 80 00

[00:00:30.304] EVT <= 1B 03 80 00 05

[00:00:30.307] EVT <= 0F 04 00 05 1B 04

[00:00:30.311] EVT <= 0B 0B 00 80 00 FF FE 0F FE DB FF 7B 87

[00:00:30.317] EVT <= 6E 00

[00:00:30.319] CMD => 1C 04 03 80 00 01

[00:00:30.323] EVT <= 0F 04 00 05 1C 04

[00:00:30.326] EVT <= 6E 00

[00:00:30.351] EVT <= 23 0D 00 80 00 01 02 0F 00 00 00 00 00 00 00

[00:00:30.352] CMD => 1C 04 03 80 00 02

[00:00:30.352] EVT <= 32 09 B1 E3 69 B5 1B 1C 01 00 05

[00:00:30.355] LOG -- hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

[00:00:30.363] EVT <= DF 0A B1 E3 69 B5 1B 1C 80 00 01 00

[00:00:30.368] EVT <= 31 06 B1 E3 69 B5 1B 1C

[00:00:30.372] EVT <= 6E 00

[00:01:00.344] EVT <= 36 07 22 B1 E3 69 B5 1B 1C

[00:01:00.345] LOG -- hci.c.429: pairing complete, status 22

[00:01:00.345] EVT <= E0 09 B1 E3 69 B5 1B 1C 80 00 22 3F

[00:01:00.349] EVT <= 0F 04 02 05 1C 04

[00:01:00.352] LOG -- hci.c.5551: gap_mitm_protection_required_for_security_level 0

[00:01:00.360] CMD => 2B 04 09 B1 E3 69 B5 1B 1C 03 00 04

[00:01:00.365] EVT <= 0E 0A 05 2B 04 0C B1 E3 69 B5 1B 1C

[00:01:00.370] EVT <= 6E 00

[00:01:00.416] EVT <= 05 04 00 80 00 22

[00:01:00.417] LOG -- hci.c.1014: Connection closed: handle 0x80, 1C:1B:B5:69:E3:B1

[00:01:00.417] LOG -- hci.c.5405: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0

[00:01:00.423] EVT <= 61 01 00

[00:01:29.701] EVT <= 04 0A 9E 4B 63 29 B4 04 0C 02 5A 01

[00:01:29.702] LOG -- hci.c.2566: Connection_incoming: 04:B4:29:63:4B:9E, type 1

[00:01:29.703] LOG -- hci.c.203: create_connection_for_addr 04:B4:29:63:4B:9E, type fd

[00:01:29.711] LOG -- hci.c.4504: sending hci_accept_connection_request

[00:01:29.717] CMD => 09 04 07 9E 4B 63 29 B4 04 01

[00:01:29.722] EVT <= 0F 04 00 05 09 04

[00:01:29.726] EVT <= 6E 00

[00:01:29.734] EVT <= 03 0B 00 81 00 9E 4B 63 29 B4 04 01 00

[00:01:29.735] LOG -- hci.c.2590: Connection_complete (status=0) 04:B4:29:63:4B:9E

[00:01:29.741] LOG -- hci.c.2610: New connection: handle 129, 04:B4:29:63:4B:9E

[00:01:29.748] LOG -- hci.c.5405: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

[00:01:29.754] EVT <= 61 01 01

[00:01:29.758] CMD => 1B 04 02 81 00

[00:01:29.761] EVT <= 1B 03 81 00 05

[00:01:29.764] EVT <= 38 04 81 00 40 1F

[00:01:29.768] ACL <= 81 20 0A 00 06 00 01 00 0A 02 02 00 02 00

[00:01:29.773] EVT <= 0F 04 00 05 1B 04

[00:01:29.777] EVT <= 0B 0B 00 81 00 BF FE 8F FE DB FF 5B 87

[00:01:29.783] EVT <= 32 09 9E 4B 63 29 B4 04 01 00 03

[00:01:29.788] LOG -- hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

[00:01:29.795] EVT <= DF 0A 9E 4B 63 29 B4 04 81 00 01 00

[00:01:29.800] EVT <= 31 06 9E 4B 63 29 B4 04

[00:01:29.805] EVT <= 6E 00

[00:01:29.807] ACL => 81 00 10 00 0C 00 01 00 0B 02 08 00 02 00 00 00 80 02 00 00

[00:01:29.815] EVT <= 6E 00

[00:01:29.817] CMD => 35 0C 05 01 81 00 01 00

[00:01:29.821] EVT <= 6E 00

[00:01:29.824] LOG -- hci.c.5551: gap_mitm_protection_required_for_security_level 2

[00:01:29.831] CMD => 2B 04 09 9E 4B 63 29 B4 04 03 00 04

[00:01:29.837] EVT <= 13 05 01 81 00 01 00

[00:01:29.840] EVT <= 0E 0A 05 2B 04 00 9E 4B 63 29 B4 04

[00:01:29.846] ACL <= 81 20 0A 00 06 00 01 00 0A 03 02 00 03 00

[00:01:29.851] EVT <= 6E 00

[00:01:29.854] ACL => 81 00 14 00 10 00 01 00 0B 03 0C 00 03 00 00 00 06 00 00 00 00 00 00 00

[00:01:30.020] EVT <= 33 0A 9E 4B 63 29 B4 04 36 FF 03 00

[00:01:30.021] LOG -- hid_keyboard_demo.c.323: SSP User Confirmation Request with numeric value '261942'

[00:01:30.029] LOG -- hid_keyboard_demo.c.324: SSP User Confirmation Auto accept

SSP User Confirmation Request with numeric value '261942'

SSP User Confirmation Auto accept

[00:01:30.045] EVT <= 13 05 01 81 00 01 00

[00:01:30.049] EVT <= 6E 00

[00:01:30.051] CMD => 35 0C 05 01 81 00 01 00

[00:01:30.056] EVT <= 6E 00

[00:01:30.058] CMD => 2C 04 06 9E 4B 63 29 B4 04

[00:01:30.063] EVT <= 0E 0A 05 2C 04 00 9E 4B 63 29 B4 04

[00:01:30.068] EVT <= 6E 00

[00:01:30.070] CMD => 1C 04 03 81 00 01

[00:01:30.074] EVT <= 6E 00

[00:01:32.408] EVT <= 36 07 00 9E 4B 63 29 B4 04

[00:01:32.409] LOG -- hci.c.429: pairing complete, status 00

[00:01:32.409] EVT <= E0 09 9E 4B 63 29 B4 04 81 00 00 3F

[00:01:32.418] EVT <= 18 17 9E 4B 63 29 B4 04 C2 3E 83 B2 7E 67 7E FD 96 E2 8F 51 3A 62 B0 47 07

[00:01:32.421] LOG -- hci.c.454: gap_store_link_key_for_bd_addr: 04:B4:29:63:4B:9E, type 7

[00:01:32.432] LOG -- btstack_link_key_db_tlv.c.152: tag_for_addr 42544c0c, tag_for_empy 42544c09, tag_for_lowest_seq_nr 42544c0f

[00:01:32.440] LOG -- btstack_link_key_db_tlv.c.166: store with tag 42544c0c

[00:01:32.447] LOG -- btstack_tlv_esp32.c.97: store tag 42544C0C

[00:01:32.455] EVT <= 0F 04 00 05 1C 04

[00:01:32.456] EVT <= 23 0D 00 81 00 01 02 0B 00 00 00 00 00 00 00

[00:01:32.462] CMD => 1C 04 03 81 00 02

[00:01:32.466] ACL <= 81 20 0C 00 08 00 01 00 02 04 04 00 01 00 41 00

[00:01:32.473] LOG -- l2cap.c.1997: create channel 0x3ffd2c18, local_cid 0x0041

[00:01:32.479] LOG -- l2cap.c.1088: L2CAP_EVENT_INCOMING_CONNECTION addr 04:B4:29:63:4B:9E handle 0x81 psm 0x1 local_cid 0x41 remote_cid 0x41

[00:01:32.491] EVT <= 72 0E 9E 4B 63 29 B4 04 81 00 01 00 41 00 41 00

[00:01:32.498] LOG -- l2cap.c.2645: L2CAP_ACCEPT_CONNECTION local_cid 0x41

[00:01:32.504] EVT <= 0F 04 00 05 1C 04

[00:01:32.508] EVT <= 23 0D 00 81 00 02 02 00 03 00 00 00 00 00 00

[00:01:32.514] LOG -- hci.c.2077: Remote features 03, bonding flags f8

[00:01:32.520] LOG -- l2cap.c.2341: remote supported features, channel 0x3ffd2c18, cid 0041 - state 17

[00:01:32.529] EVT <= 6E 00

[00:01:32.532] ACL => 81 00 10 00 0C 00 01 00 03 04 08 00 41 00 41 00 00 00 00 00

[00:01:32.540] EVT <= 6E 00

[00:01:32.542] ACL => 81 00 10 00 0C 00 01 00 04 01 08 00 41 00 00 00 01 02 9B 06

[00:01:32.549] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x41

[00:01:32.555] LOG -- l2cap.c.1255: l2cap_start_rtx for local cid 0x41

[00:01:32.562] EVT <= 13 05 01 81 00 01 00

[00:01:32.565] EVT <= 13 05 01 81 00 01 00

[00:01:32.569] ACL <= 81 20 10 00 0C 00 01 00 04 05 08 00 41 00 00 00 01 02 00 04

[00:01:32.577] LOG -- l2cap.c.2856: L2CAP signaling handler code 4, state 11

[00:01:32.583] LOG -- l2cap.c.2701: Remote MTU 1024

[00:01:32.588] ACL <= 81 20 0E 00 0A 00 01 00 05 01 06 00 41 00 00 00 00 00

[00:01:32.595] LOG -- l2cap.c.2856: L2CAP signaling handler code 5, state 11

[00:01:32.602] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x41

[00:01:32.608] LOG -- l2cap.c.2786: l2cap_signaling_handle_configure_response

[00:01:32.615] EVT <= 6E 00

[00:01:32.617] ACL => 81 00 12 00 0E 00 01 00 05 05 0A 00 41 00 00 00 00 00 01 02 00 04

[00:01:32.625] LOG -- l2cap.c.1054: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 04:B4:29:63:4B:9E handle 0x81 psm 0x1 local_cid 0x41 remote_cid 0x41 local_mtu 1691, remote_mtu 1024, flush_timeout 0

[00:01:32.642] EVT <= 70 18 00 9E 4B 63 29 B4 04 81 00 01 00 41 00 41 00 9B 06 00 04 00 00 01 00 00

[00:01:32.651] EVT <= 13 05 01 81 00 01 00

[00:01:32.655] ACL <= 81 20 18 00 14 00 41 00 06 00 00 00 0F 35 03 19 12 00 03 F0 35 05 0A 00 00 FF FF 00

[00:01:32.665] EVT <= 6E 00

[00:01:32.667] EVT <= 78 02 41 00

[00:01:32.670] ACL => 81 00 4F 00 4B 00 41 00 07 00 00 00 46 00 43 36 00 40 36 00 3D 09 00 00 0A 00 01 00 03 09 00 01 36 00 03 19 12 00 09 00 05 36 00 03 19 10 02 09 02 00 09 01 03 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:01:32.694] EVT <= 6E 00

[00:01:32.696] CMD => 35 0C 05 01 81 00 04 00

[00:01:32.701] EVT <= 6E 00

[00:01:32.707] EVT <= 13 05 01 81 00 01 00

[00:01:32.710] ACL <= 81 20 0C 00 08 00 01 00 06 06 04 00 41 00 41 00

[00:01:32.713] LOG -- l2cap.c.2856: L2CAP signaling handler code 6, state 12

[00:01:32.720] ACL => 81 00 0C 00 08 00 01 00 07 06 04 00 41 00 41 00

[00:01:32.727] LOG -- l2cap.c.1082: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41

[00:01:32.733] EVT <= 71 02 41 00

[00:01:32.736] LOG -- l2cap.c.2003: free channel 0x3ffd2c18, local_cid 0x0041

[00:01:32.743] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x41

[00:01:32.749] EVT <= 13 05 01 81 00 01 00

[00:01:32.753] ACL <= 81 20 0C 00 08 00 01 00 02 07 04 00 01 00 45 00

[00:01:32.759] LOG -- l2cap.c.1997: create channel 0x3ffd2c18, local_cid 0x0042

[00:01:32.766] LOG -- l2cap.c.1088: L2CAP_EVENT_INCOMING_CONNECTION addr 04:B4:29:63:4B:9E handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x45

[00:01:32.779] EVT <= 72 0E 9E 4B 63 29 B4 04 81 00 01 00 42 00 45 00

[00:01:32.785] LOG -- l2cap.c.2645: L2CAP_ACCEPT_CONNECTION local_cid 0x42

[00:01:32.792] EVT <= 6E 00

[00:01:32.794] ACL => 81 00 10 00 0C 00 01 00 03 07 08 00 42 00 45 00 00 00 00 00

[00:01:32.802] EVT <= 6E 00

[00:01:32.804] ACL => 81 00 10 00 0C 00 01 00 04 02 08 00 45 00 00 00 01 02 9B 06

[00:01:32.812] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x42

[00:01:32.818] LOG -- l2cap.c.1255: l2cap_start_rtx for local cid 0x42

[00:01:32.824] EVT <= 6E 00

[00:01:32.827] CMD => 35 0C 05 01 81 00 02 00

[00:01:32.831] EVT <= 6E 00

[00:01:32.853] ACL <= 81 20 10 00 0C 00 01 00 04 08 08 00 42 00 00 00 01 02 00 04

[00:01:32.854] LOG -- l2cap.c.2856: L2CAP signaling handler code 4, state 11

[00:01:32.856] LOG -- l2cap.c.2701: Remote MTU 1024

[00:01:32.861] ACL => 81 00 12 00 0E 00 01 00 05 08 0A 00 45 00 00 00 00 00 01 02 00 04

[00:01:32.869] EVT <= 13 05 01 81 00 01 00

[00:01:32.873] EVT <= 13 05 01 81 00 01 00

[00:01:32.877] ACL <= 81 20 0E 00 0A 00 01 00 05 02 06 00 42 00 00 00 00 00

[00:01:32.883] LOG -- l2cap.c.2856: L2CAP signaling handler code 5, state 11

[00:01:32.890] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x42

[00:01:32.896] LOG -- l2cap.c.2786: l2cap_signaling_handle_configure_response

[00:01:32.903] LOG -- l2cap.c.1054: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 04:B4:29:63:4B:9E handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x45 local_mtu 1691, remote_mtu 1024, flush_timeout 0

[00:01:32.920] EVT <= 70 18 00 9E 4B 63 29 B4 04 81 00 01 00 42 00 45 00 9B 06 00 04 00 00 01 00 00

[00:01:32.929] EVT <= 13 05 01 81 00 01 00

[00:01:32.933] ACL <= 81 20 18 00 14 00 42 00 06 00 00 00 0F 35 03 19 01 00 03 F0 35 05 0A 00 00 FF FF 00

[00:01:32.943] EVT <= 6E 00

[00:01:32.945] EVT <= 78 02 42 00

[00:01:32.948] ACL => 81 00 1D 01 19 01 45 00 07 00 00 01 14 01 11 36 01 0E 36 01 0B 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 01 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 0C 09 0C 80 09 02 0D 28 01 09 02

 0E 28 00 09 02 0F 09 FF FF 09 02 10 09 FF FF 00

[00:01:33.026] EVT <= 6E 00

[00:01:33.028] CMD => 35 0C 05 01 81 00 03 00

[00:01:33.032] EVT <= 13 05 01 81 00 01 00

[00:01:33.036] ACL <= 81 20 0C 00 08 00 01 00 06 09 04 00 42 00 45 00

[00:01:33.043] LOG -- l2cap.c.2856: L2CAP signaling handler code 6, state 12

[00:01:33.049] EVT <= 6E 00

[00:01:33.052] ACL => 81 00 0C 00 08 00 01 00 07 09 04 00 42 00 45 00

[00:01:33.058] LOG -- l2cap.c.1082: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x42

[00:01:33.065] EVT <= 71 02 42 00

[00:01:33.068] LOG -- l2cap.c.2003: free channel 0x3ffd2c18, local_cid 0x0042

[00:01:33.075] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x42

[00:01:33.081] EVT <= 13 05 01 81 00 01 00

[00:01:33.085] EVT <= 6E 00

[00:01:33.088] CMD => 35 0C 05 01 81 00 01 00

[00:01:33.092] EVT <= 6E 00

[00:01:33.153] EVT <= 08 04 00 81 00 02

[00:01:33.153] CMD => 08 14 02 81 00

[00:01:33.154] EVT <= 0E 07 05 08 14 00 81 00 10

[00:01:33.155] LOG -- hci.c.2265: Handle 0081 key Size: 16

[00:01:33.159] LOG -- hci.c.5436: hci_emit_security_level 2 for handle 81

[00:01:33.165] EVT <= D8 03 81 00 02

[00:01:33.169] LOG -- l2cap.c.2361: l2cap - security level update for handle 0x0081

[00:01:33.176] ACL <= 81 20 0C 00 08 00 01 00 02 0A 04 00 11 00 40 00

[00:01:33.182] LOG -- l2cap.c.1997: create channel 0x3ffd2c18, local_cid 0x0043

[00:01:33.189] LOG -- l2cap.c.1088: L2CAP_EVENT_INCOMING_CONNECTION addr 04:B4:29:63:4B:9E handle 0x81 psm 0x11 local_cid 0x43 remote_cid 0x40

[00:01:33.202] EVT <= 72 0E 9E 4B 63 29 B4 04 81 00 11 00 43 00 40 00

[00:01:33.208] LOG -- l2cap.c.2645: L2CAP_ACCEPT_CONNECTION local_cid 0x43

[00:01:33.215] EVT <= 6E 00

[00:01:33.217] ACL => 81 00 10 00 0C 00 01 00 03 0A 08 00 43 00 40 00 00 00 00 00

[00:01:33.225] EVT <= 6E 00

[00:01:33.227] ACL => 81 00 10 00 0C 00 01 00 04 03 08 00 40 00 00 00 01 02 64 00

[00:01:33.235] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x43

[00:01:33.241] LOG -- l2cap.c.1255: l2cap_start_rtx for local cid 0x43

[00:01:33.247] EVT <= 13 05 01 81 00 01 00

[00:01:33.251] ACL <= 81 20 10 00 0C 00 01 00 04 0B 08 00 43 00 00 00 01 02 80 02

[00:01:33.258] LOG -- l2cap.c.2856: L2CAP signaling handler code 4, state 11

[00:01:33.265] LOG -- l2cap.c.2701: Remote MTU 640

[00:01:33.269] ACL <= 81 20 0E 00 0A 00 01 00 05 03 06 00 43 00 00 00 00 00

[00:01:33.276] LOG -- l2cap.c.2856: L2CAP signaling handler code 5, state 11

[00:01:33.283] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x43

[00:01:33.289] LOG -- l2cap.c.2786: l2cap_signaling_handle_configure_response

[00:01:33.296] EVT <= 13 05 01 81 00 01 00

[00:01:33.300] EVT <= 6E 00

[00:01:33.302] ACL => 81 00 12 00 0E 00 01 00 05 0B 0A 00 40 00 00 00 00 00 01 02 64 00

[00:01:33.310] LOG -- l2cap.c.1054: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 04:B4:29:63:4B:9E handle 0x81 psm 0x11 local_cid 0x43 remote_cid 0x40 local_mtu 100, remote_mtu 640, flush_timeout 0

[00:01:33.327] EVT <= 70 18 00 9E 4B 63 29 B4 04 81 00 11 00 43 00 40 00 64 00 80 02 00 00 01 00 00

[00:01:33.336] EVT <= 13 05 01 81 00 01 00

[00:01:33.340] ACL <= 81 20 0C 00 08 00 01 00 02 0C 04 00 13 00 46 00

[00:01:33.346] LOG -- l2cap.c.1997: create channel 0x3ffd2c8c, local_cid 0x0044

[00:01:33.353] LOG -- l2cap.c.1088: L2CAP_EVENT_INCOMING_CONNECTION addr 04:B4:29:63:4B:9E handle 0x81 psm 0x13 local_cid 0x44 remote_cid 0x46

[00:01:33.366] EVT <= 72 0E 9E 4B 63 29 B4 04 81 00 13 00 44 00 46 00

[00:01:33.372] LOG -- l2cap.c.2645: L2CAP_ACCEPT_CONNECTION local_cid 0x44

[00:01:33.379] EVT <= 6E 00

[00:01:33.381] ACL => 81 00 10 00 0C 00 01 00 03 0C 08 00 44 00 46 00 00 00 00 00

[00:01:33.389] EVT <= 6E 00

[00:01:33.391] ACL => 81 00 10 00 0C 00 01 00 04 04 08 00 46 00 00 00 01 02 64 00

[00:01:33.399] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x44

[00:01:33.405] LOG -- l2cap.c.1255: l2cap_start_rtx for local cid 0x44

[00:01:33.411] EVT <= 13 05 01 81 00 01 00

[00:01:33.415] ACL <= 81 20 10 00 0C 00 01 00 04 0D 08 00 44 00 00 00 01 02 80 02

[00:01:33.422] LOG -- l2cap.c.2856: L2CAP signaling handler code 4, state 11

[00:01:33.429] LOG -- l2cap.c.2701: Remote MTU 640

[00:01:33.433] EVT <= 13 05 01 81 00 01 00

[00:01:33.437] ACL <= 81 20 0E 00 0A 00 01 00 05 04 06 00 44 00 00 00 00 00

[00:01:33.444] LOG -- l2cap.c.2856: L2CAP signaling handler code 5, state 11

[00:01:33.451] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x44

[00:01:33.457] LOG -- l2cap.c.2786: l2cap_signaling_handle_configure_response

[00:01:33.464] EVT <= 6E 00

[00:01:33.467] ACL => 81 00 12 00 0E 00 01 00 05 0D 0A 00 46 00 00 00 00 00 01 02 64 00

[00:01:33.474] LOG -- l2cap.c.1054: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 04:B4:29:63:4B:9E handle 0x81 psm 0x13 local_cid 0x44 remote_cid 0x46 local_mtu 100, remote_mtu 640, flush_timeout 0

[00:01:33.491] EVT <= 70 18 00 9E 4B 63 29 B4 04 81 00 13 00 44 00 46 00 64 00 80 02 00 00 01 00 00

HID Connected, please start typing...

[00:01:33.503] ACL <= 81 20 06 00 02 00 43 00 90 00

[00:01:33.508] EVT <= 13 05 01 81 00 01 00

[00:01:33.512] EVT <= 6E 00

[00:01:33.515] EVT <= 78 02 43 00

[00:01:33.518] ACL => 81 00 05 00 01 00 40 00 03

[00:01:33.522] EVT <= 6E 00

[00:01:33.525] CMD => 35 0C 05 01 81 00 07 00

[00:01:33.529] EVT <= 6E 00

[00:01:33.532] EVT <= 13 05 01 81 00 01 00

[00:02:03.545] EVT <= 14 06 00 81 00 02 36 00

Thanks!

Best Regards,

Danny

[Chan Danny]

Hi  Matthias,

1. If want to use HFP + HID Classic, I need to execute two BTStack in parallel or how can I run 2 classic profiles in one process?

2. In the mean time, I debug the HFP + HIDS after adding the logs. 

    I can have 2 profiles paired, keypad works. 

    Then I connect audio, fails to connect with error status 0x1f (Unspecified Error!), then 0x12 and 0x1d. What is Unspecified Error refer!?

    If audio can be connected, the error status is 0.    

    And then HCI disconnected, keypad also not work. Can it reveal anything from the logs below?

3. By the way, if audio can be connected, keypad also not work, I can see no related BT command is sent, is it normal?

The following is the error logs:

....

[00:05:56.610] LOG -- hfp_hf.c.935: hfp: codec confirmed: mSBC

[00:05:56.616] LOG -- hfp.c.236: HFP_TX AT+BCS=2

[00:05:56.620] ACL => 80 00 12 00 0E 00 40 00 09 EF 12 00 41 54 2B 42 43 53 3D 32 0D 40

[00:05:56.628] EVT <= 6E 00

[00:05:56.631] CMD => 35 0C 05 01 80 00 01 00

[00:05:56.635] EVT <= 6E 00

[00:05:56.643] EVT <= 13 05 01 80 00 01 00

[00:05:56.646] ACL <= 80 20 0F 00 0B 00 43 00 0B FF 0D 01 0D 0A 4F 4B 0D 0A 86

[00:05:56.648] LOG -- rfcomm.c.1440: RFCOMM data UIH_PF, new credits channel 0x03: 1, now 32

[00:05:56.656] LOG -- hfp.c.1953: HFP_HF_RX: '\r\nOK\r\n'

[00:05:56.661] LOG -- hfp.c.1228: command string 'OK', handsfree 1 -> cmd id 3

[00:05:56.668] CMD => 35 0C 05 01 80 00 01 00

[00:05:56.673] EVT <= 1B 03 80 00 01

[00:05:56.676] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 02

[00:05:56.681] LOG -- hci.c.2566: Connection_incoming: 1C:1B:B5:69:E3:B1, type 2

[00:05:56.688] LOG -- hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fc

[00:05:56.696] LOG -- hfp.c.782: accept sco 2

[00:05:56.700] EVT <= 3E 0B 07 00 00 FB 00 48 01 FB 00 4A 01

[00:05:56.706] EVT <= 6E 00

[00:05:56.708] LOG -- hfp.c.1801: HFP: sending hci_accept_connection_request, packet types 0x0388, sco_voice_setting 0x43

[00:05:56.719] CMD => 29 04 15 B1 E3 69 B5 1B 1C 40 1F 00 00 40 1F 00 00 0C 00 43 00 02 88 03

[00:05:56.727] EVT <= 0F 04 00 05 29 04

[00:05:56.731] EVT <= 6E 00

[00:05:56.762] EVT <= 2C 11 1F 80 01 B1 E3 69 B5 1B 1C 02 0C 02 3C 00 3C 00 03

[00:05:56.763] LOG -- hci.c.2622: Synchronous Connection Complete (status=31) 1C:1B:B5:69:E3:B1

[00:05:56.767] LOG -- hfp.c.715: (e)SCO Connection failed 0x1f

[00:05:56.772] LOG -- hfp.c.731: T2/T1 failed, fallback to CVSD - D1

[00:05:56.778] LOG -- hfp.c.742: e)SCO Connection: try new link_setting 8

[00:05:56.785] LOG -- hfp.c.1749: hfp_setup_synchronous_connection using setting nr 8

[00:05:56.792] CMD => 28 04 11 80 00 40 1F 00 00 40 1F 00 00 2B 42 60 00 43 FA 03

[00:05:56.800] EVT <= 1B 03 80 00 05

[00:05:56.803] EVT <= 0F 04 12 05 28 04

[00:05:56.807] LOG -- hfp.c.715: (e)SCO Connection failed 0x12

Audio connection establishment failed with status 0x12

[00:05:56.817] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 02

[00:05:56.822] LOG -- hci.c.2566: Connection_incoming: 1C:1B:B5:69:E3:B1, type 2

[00:05:56.829] LOG -- hfp.c.782: accept sco 2

[00:05:56.834] EVT <= 6E 00

[00:05:56.837] LOG -- hfp.c.1801: HFP: sending hci_accept_connection_request, packet types 0x0388, sco_voice_setting 0x60

[00:05:56.847] CMD => 29 04 15 B1 E3 69 B5 1B 1C 40 1F 00 00 40 1F 00 00 0C 00 60 00 02 88 03

[00:05:56.856] EVT <= 0F 04 00 05 29 04

[00:05:56.859] EVT <= 2C 11 1D 80 01 B1 E3 69 B5 1B 1C 02 06 04 1E 00 1E 00 03

[00:05:56.866] LOG -- hci.c.2622: Synchronous Connection Complete (status=29) 1C:1B:B5:69:E3:B1

[00:05:56.875] LOG -- hfp.c.715: (e)SCO Connection failed 0x1d

Audio connection establishment failed with status 0x1d

[00:05:56.885] EVT <= 6E 00

[00:05:57.009] EVT <= 1B 03 80 00 01

[00:05:57.017] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 02

[00:05:57.018] LOG -- hci.c.2566: Connection_incoming: 1C:1B:B5:69:E3:B1, type 2

[00:05:57.019] LOG -- hfp.c.782: accept sco 2

[00:05:57.023] LOG -- hfp.c.1801: HFP: sending hci_accept_connection_request, packet types 0x0388, sco_voice_setting 0x60

[00:05:57.033] CMD => 29 04 15 B1 E3 69 B5 1B 1C 40 1F 00 00 40 1F 00 00 0C 00 60 00 02 88 03

[00:05:57.042] EVT <= 0F 04 00 05 29 04

[00:05:57.046] EVT <= 2C 11 1D 80 01 B1 E3 69 B5 1B 1C 02 0C 06 3C 00 3C 00 03

[00:05:57.053] LOG -- hci.c.2622: Synchronous Connection Complete (status=29) 1C:1B:B5:69:E3:B1

[00:05:57.061] LOG -- hfp.c.715: (e)SCO Connection failed 0x1d

Audio connection establishment failed with status 0x1d

[00:05:57.071] EVT <= 1B 03 80 00 05

[00:05:57.075] EVT <= 6E 00

[00:05:57.088] EVT <= 04 0A B1 E3 69 B5 1B 1C 0C 01 2A 02

[00:05:57.089] LOG -- hci.c.2566: Connection_incoming: 1C:1B:B5:69:E3:B1, type 2

[00:05:57.092] LOG -- hfp.c.782: accept sco 2

[00:05:57.096] LOG -- hfp.c.1801: HFP: sending hci_accept_connection_request, packet types 0x0388, sco_voice_setting 0x60

[00:05:57.107] CMD => 29 04 15 B1 E3 69 B5 1B 1C 40 1F 00 00 40 1F 00 00 0C 00 60 00 02 88 03

[00:05:57.116] EVT <= 0F 04 00 05 29 04

[00:05:57.119] EVT <= 2C 11 1D 80 01 B1 E3 69 B5 1B 1C 02 06 04 1E 00 1E 00 03

[00:05:57.126] LOG -- hci.c.2622: Synchronous Connection Complete (status=29) 1C:1B:B5:69:E3:B1

[00:05:57.134] LOG -- hfp.c.715: (e)SCO Connection failed 0x1d

Audio connection establishment failed with status 0x1d

[00:05:57.145] EVT <= 6E 00

[00:06:26.829] EVT <= 05 04 00 80 00 22

[00:06:26.830] LOG -- l2cap.c.1082: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x43

[00:06:26.830] EVT <= 71 02 43 00

[00:06:26.832] LOG -- rfcomm.c.1168: L2CAP_EVENT_CHANNEL_CLOSED cid 0x43, mult 0x3ffdafd4

[00:06:26.840] LOG -- rfcomm.c.1170: L2CAP_EVENT_CHANNEL_CLOSED state 7

[00:06:26.847] LOG -- rfcomm.c.288: RFCOMM_EVENT_CHANNEL_CLOSED cid 0x03

[00:06:26.853] EVT <= 81 02 03 00

Service level connection released.

[00:06:26.860] LOG -- l2cap.c.2003: free channel 0x3ffdaf60, local_cid 0x0043

[00:06:26.866] LOG -- l2cap.c.1246: l2cap_stop_rtx for local cid 0x43

Disconnected

[00:06:26.874] LOG -- hci.c.1014: Connection closed: handle 0x80, 1C:1B:B5:69:E3:B1

[00:06:26.881] LOG -- hci.c.5405: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 2

[00:06:26.887] EVT <= 61 01 02

Thanks!

Best Regards,

Danny 

[Matthias Ringwald]

Hi Danny

If you use the ESP32, please convert the log output to .pklg using tool/create_packet_log.py so we can open it in Wireshark / PacketLogger directly.

BTstack can handle most combinations of Classic and LE profiles by individually setting them up, like you did before. (HFP AG or HF and HID Device or Host is fine).

In your previous ESP32 log, there's an issue with pairing I need to try to reproduce it and dig deeper. In any case, it is only related to Classic pairing, independent from the actually used Classic profiles.

In the log below, the SCO (voice) connection setup fails first with an 'unspecified error', laster other configurations are rejected by the remote device.

I suggest to fully test HFP and HID Classic individually on a desktop platform first, e.g. Mac/Win/Linux and a USB Bluetooth Dongle, then re-test on the ESP32.
If both work individually, they can be combined on the desktop, and when that works, you can move everything to ESP32.

On the desktop, packet logs are enabled by default and already in the .pklg format. So, please try hfp_hf_demo and hid_keyboard_demo on a desktop. Both should work right away.
If not, please post logs.

Cheers
Matthias


> On 6 Sep 2021, at 19:24, Chan Danny <dannychan...@gmail.com> wrote:
>
> Hi Matthias,

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/ad1b3477-00f9-4fe4-80ed-bacb8759f9cen%40googlegroups.com.

[Matthias Ringwald]

Hi Danny

I've tried the spp streamer example and don't get the issue from your log - it seems to depend on the timing and behaviour of the remote device, too.

Anyway, I've made changes to the Classic pairing logic on BTstack's develop branch. The change avoids the situation where BTstack waits for the response to the remote feature request while the Bluetooth Controller waits for the User Confirmation Response from BTstack.

Please pull the version on the develop branch, run the integration script, and re-run the hid_keyboard_demo with hci logging enabled and post your logs/.pklg file to see if the update avoids at least this issue (we can then look at the next one...)

Cheers
Matthias

[Chan Danny]

Hi Matthias,

Thank you and I will try.

But I am following your idea to test on desktop platform with a USB BT dongle. 

I used Zadig to replace the driver and there is a bluetooth radio in device manager (attached picture).

I compiled and run the example, I can see from the log that it can communicate with the driver, however, it can not be discovered by other PCs/Phones! 

It seems the dongle is not working, but I've already verified working with manufacturer's driver in another PC. 

Anything can be revealed from the logs??

By the way I can only attach pictures, how can I attach other files like logs in the post??

1 0.000000 PKTLOG 58 hci_transport_h2_winusb.c.376: registering packet handler

2 0.000154 PKTLOG 55 l2cap.c.3863: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535

3 0.003184 PKTLOG 54 l2cap.c.3863: L2CAP_REGISTER_SERVICE psm 0x13 mtu 100

4 0.003199 PKTLOG 54 l2cap.c.3863: L2CAP_REGISTER_SERVICE psm 0x11 mtu 100

5 0.003272 PKTLOG 49 hci.c.3890: hci_power_control: 1, current mode 0

6 0.003295 PKTLOG 80 hci_transport_h2_winusb.c.1070: WinUSB                         00007ffcfdc00000

7 0.003308 PKTLOG 80 hci_transport_h2_winusb.c.1071: WinUsb_QueryPipeEx             00007ffcfdc01210

8 0.003319 PKTLOG 80 hci_transport_h2_winusb.c.1072: WinUsb_RegisterIsochBuffer     00007ffcfdc03800

9 0.003329 PKTLOG 80 hci_transport_h2_winusb.c.1073: WinUsb_ReadIsochPipe           00007ffcfdc04180

10 0.003340 PKTLOG 80 hci_transport_h2_winusb.c.1074: WinUsb_ReadIsochPipeAsap       00007ffcfdc04130

11 0.003350 PKTLOG 80 hci_transport_h2_winusb.c.1075: WinUsb_WriteIsochPipe          00007ffcfdc03da0

12 0.003361 PKTLOG 80 hci_transport_h2_winusb.c.1076: WinUsb_WriteIsochPipeAsap      00007ffcfdc03d70

13 0.003371 PKTLOG 80 hci_transport_h2_winusb.c.1077: WinUsb_UnregisterIsochBuffer   00007ffcfdc039b0

14 0.003382 PKTLOG 80 hci_transport_h2_winusb.c.1078: WinUsb_GetCurrentFrameNumber   00007ffcfdc03600

15 0.004268 PKTLOG 82 hci_transport_h2_winusb.c.1119: usb_open: SetupDiGetClassDevs -> 00000243c411a110

16 0.004305 PKTLOG 138 hci_transport_h2_winusb.c.1169: usb_open: Device Path: \\?\usb#vid_0bda&pid_0316#20120501030900000#{a5dcbf10-6530-11d2-901f-00c04fb951ed}

17 0.004341 PKTLOG 68 hci_transport_h2_winusb.c.946: Opening USB device: 00000000000000f0

18 0.004379 PKTLOG 67 hci_transport_h2_winusb.c.1058: usb_try_open_device: last error 31

19 0.004394 PKTLOG 61 hci_transport_h2_winusb.c.1196: usb_open: Device open failed

20 0.004420 PKTLOG 125 hci_transport_h2_winusb.c.1169: usb_open: Device Path: \\?\usb#vid_13d3&pid_56a6#0001#{a5dcbf10-6530-11d2-901f-00c04fb951ed}

21 0.004449 PKTLOG 68 hci_transport_h2_winusb.c.946: Opening USB device: 00000000000000f0

22 0.065418 PKTLOG 66 hci_transport_h2_winusb.c.1058: usb_try_open_device: last error 8

23 0.065461 PKTLOG 61 hci_transport_h2_winusb.c.1196: usb_open: Device open failed

24 0.065498 PKTLOG 133 hci_transport_h2_winusb.c.1169: usb_open: Device Path: \\?\usb#vid_0bda&pid_8771#00e04c239987#{a5dcbf10-6530-11d2-901f-00c04fb951ed}

25 0.065539 PKTLOG 68 hci_transport_h2_winusb.c.946: Opening USB device: 00000000000000f0

26 0.065650 PKTLOG 55 hci_transport_h2_winusb.c.982: Claiming interface 1...

27 0.065663 PKTLOG 61 hci_transport_h2_winusb.c.988: Claiming interface 1: success

28 0.065674 PKTLOG 55 hci_transport_h2_winusb.c.750: Scanning USB Entpoints:

29 0.065719 PKTLOG 103 hci_transport_h2_winusb.c.763: Interface #0, Alt #0, Pipe idx #0: type 3, id 0x81, max packet size 16,

30 0.065729 PKTLOG 60 hci_transport_h2_winusb.c.769: -> using 0x81 for HCI Events

31 0.065739 PKTLOG 103 hci_transport_h2_winusb.c.763: Interface #0, Alt #0, Pipe idx #1: type 2, id 0x02, max packet size 64,

32 0.065749 PKTLOG 62 hci_transport_h2_winusb.c.779: -> using 0x02 for ACL Data Out

33 0.065759 PKTLOG 103 hci_transport_h2_winusb.c.763: Interface #0, Alt #0, Pipe idx #2: type 2, id 0x82, max packet size 64,

34 0.065769 PKTLOG 61 hci_transport_h2_winusb.c.775: -> using 0x82 for ACL Data In

35 0.065779 PKTLOG 139 hci_transport_h2_winusb.c.803: Interface #1, Alt #1, Pipe idx #0: type 1, id 0x03, max packet size 9, interval 1, max bytes per interval 9

36 0.065789 PKTLOG 62 hci_transport_h2_winusb.c.814: -> using 0x03 for SCO Data Out

37 0.065799 PKTLOG 139 hci_transport_h2_winusb.c.803: Interface #1, Alt #1, Pipe idx #1: type 1, id 0x83, max packet size 9, interval 1, max bytes per interval 9

38 0.065808 PKTLOG 61 hci_transport_h2_winusb.c.810: -> using 0x83 for SCO Data In

39 0.065818 PKTLOG 73 hci_transport_h2_winusb.c.1002: Size of packet descriptors for SCO IN288

40 0.065921 PKTLOG 71 hci_transport_h2_winusb.c.1193: usb_open: Device opened, stop scanning

41 0.067506 PKTLOG 54 hci_transport_h2_winusb.c.1210: usb_open: done, r = 0

42 0.067538 PKTLOG 34 hci.c.5352: BTSTACK_EVENT_STATE 1

43 0.067548 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

44 0.067602 host controller HCI_CMD 4 Sent Reset

45 0.067769 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

46 0.078887 controller host HCI_EVT 7 Rcvd Command Complete (Reset)

47 0.079129 host controller HCI_CMD 4 Sent Read Local Version Information

48 0.079433 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

49 0.080756 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Version Information)

50 0.080789 PKTLOG 33 hci.c.2232: Manufacturer: 0x005d

51 0.080809 host controller HCI_CMD 4 Sent Read Local Name

52 0.080939 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

53 0.096772 controller host HCI_EVT 255 Rcvd Command Complete (Read Local Name)

54 0.096860 PKTLOG 35 hci.c.2138: local name: RTK_BT_5.0

55 0.096877 PKTLOG 52 hci.c.1810: Received local name, need baud change 0

56 0.096888 host controller HCI_CMD 4 Sent Read Local Supported Commands

57 0.097009 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

58 0.102752 controller host HCI_EVT 71 Rcvd Command Complete (Read Local Supported Commands)

59 0.102769 PKTLOG 53 hci.c.2250: Local supported commands summary ff - 1f

60 0.102781 host controller HCI_CMD 4 Sent Read BD ADDR

61 0.102906 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

62 0.104747 controller host HCI_EVT 13 Rcvd Command Complete (Read BD ADDR)

63 0.104762 PKTLOG 65 hci.c.2193: Local Address, Status: 0x00: Addr: 8C:88:2B:32:5D:6A

64 0.104773 host controller HCI_CMD 4 Sent Read Buffer Size

65 0.104893 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

66 0.106747 controller host HCI_EVT 14 Rcvd Command Complete (Read Buffer Size)

67 0.106761 PKTLOG 102 hci.c.2153: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 6 / SCO size 255, count 12

68 0.106772 host controller HCI_CMD 4 Sent Read Local Supported Features

69 0.106884 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

70 0.108746 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Supported Features)

71 0.108776 PKTLOG 38 hci.c.2218: Packet types cc18, eSCO 1

72 0.108787 PKTLOG 43 hci.c.2221: BR/EDR support 1, LE support 1

73 0.108798 host controller HCI_CMD 12 Sent Set Event Mask

74 0.108924 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

75 0.110752 controller host HCI_EVT 7 Rcvd Command Complete (Set Event Mask)

76 0.110770 host controller HCI_CMD 5 Sent Write Simple Pairing Mode

77 0.110898 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

78 0.112749 controller host HCI_EVT 7 Rcvd Command Complete (Write Simple Pairing Mode)

79 0.112765 host controller HCI_CMD 6 Sent Write Page Timeout

80 0.112884 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

81 0.114747 controller host HCI_EVT 7 Rcvd Command Complete (Write Page Timeout)

82 0.114761 host controller HCI_CMD 6 Sent Write Default Link Policy Settings

83 0.114882 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

84 0.116746 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Link Policy Settings)

85 0.116760 host controller HCI_CMD 7 Sent Write Class of Device

86 0.116883 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

87 0.118747 controller host HCI_EVT 7 Rcvd Command Complete (Write Class of Device)

88 0.118768 host controller HCI_CMD 252 Sent Change Local Name

89 0.119129 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

90 0.120750 controller host HCI_EVT 7 Rcvd Command Complete (Change Local Name)

91 0.120767 host controller HCI_CMD 245 Sent Write Extended Inquiry Response

92 0.121098 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

93 0.122747 controller host HCI_EVT 7 Rcvd Command Complete (Write Extended Inquiry Response)

94 0.122761 host controller HCI_CMD 5 Sent Write Inquiry Mode

95 0.122880 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

96 0.124747 controller host HCI_EVT 7 Rcvd Command Complete (Write Inquiry Mode)

97 0.124761 host controller HCI_CMD 5 Sent Write Secure Connections Host Support

98 0.124880 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

99 0.126747 controller host HCI_EVT 7 Rcvd Command Complete (Write Secure Connections Host Support)

100 0.126761 host controller HCI_CMD 5 Sent Write Scan Enable

101 0.126882 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

102 0.128747 controller host HCI_EVT 7 Rcvd Command Complete (Write Scan Enable)

103 0.128762 PKTLOG 49 hci.c.5478: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1

104 0.128771 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

105 0.128782 host controller HCI_CMD 5 Sent Write SCO Flow Control Enable

106 0.128902 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

107 0.130752 controller host HCI_EVT 7 Rcvd Command Complete (Write SCO Flow Control Enable)

108 0.130772 host controller HCI_CMD 5 Sent Write Default Erroneous Data Reporting

109 0.130896 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

110 0.132747 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Erroneous Data Reporting)

111 0.132761 host controller HCI_CMD 4 Sent LE Read Buffer Size [v1]

112 0.132880 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

113 0.134746 controller host HCI_EVT 10 Rcvd Command Complete (LE Read Buffer Size [v1])

114 0.134760 PKTLOG 55 hci.c.2175: hci_le_read_buffer_size: size 251, count 8

115 0.134771 host controller HCI_CMD 6 Sent Write LE Host Supported

116 0.134885 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

117 0.136746 controller host HCI_EVT 7 Rcvd Command Complete (Write LE Host Supported)

118 0.136760 PKTLOG 34 hci.c.1918: Supported commands 30

119 0.136771 host controller HCI_CMD 12 Sent LE Set Event Mask

120 0.136890 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

121 0.138746 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Event Mask)

122 0.138761 host controller HCI_CMD 4 Sent LE Read Maximum Data Length

123 0.138879 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

124 0.140778 controller host HCI_EVT 15 Rcvd Command Complete (LE Read Maximum Data Length)

125 0.140801 PKTLOG 77 hci.c.2182: hci_le_read_maximum_data_length: tx octets 251, tx time 17040 us

126 0.140813 host controller HCI_CMD 8 Sent LE Write Suggested Default Data Length

127 0.140942 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

128 0.142750 controller host HCI_EVT 7 Rcvd Command Complete (LE Write Suggested Default Data Length)

129 0.142766 host controller HCI_CMD 4 Sent LE Read White List Size

130 0.142884 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

131 0.144748 controller host HCI_EVT 8 Rcvd Command Complete (LE Read White List Size)

132 0.144761 PKTLOG 49 hci.c.2188: hci_le_read_white_list_size: size 32

133 0.144772 host controller HCI_CMD 11 Sent LE Set Scan Parameters

134 0.144891 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

135 0.146746 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Parameters)

136 0.146760 PKTLOG 47 hci.c.1668: hci_init_done -> HCI_STATE_WORKING

137 0.146770 PKTLOG 34 hci.c.5352: BTSTACK_EVENT_STATE 2

138 0.146779 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

139 0.148612 PKTLOG 63 btstack_tlv_posix.c.172: open db btstack_8C:88:2B:32:5D:6A.tlv

140 0.148911 PKTLOG 47 btstack_tlv_posix.c.236: failed to create file

141 0.148936 PKTLOG 48 btstack_tlv.c.48: TLV Instance 00007ff7fe56b200

142 0.148954 PKTLOG 54 le_device_db_tlv.c.159: num valid le device entries 0

143 0.148966 host controller HCI_CMD 5 Sent LE Set Address Resolution Enable

144 0.149086 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

145 0.150748 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Address Resolution Enable)

146 0.150762 host controller HCI_CMD 4 Sent LE Read Resolving List Size

147 0.150908 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

148 0.152748 controller host HCI_EVT 8 Rcvd Command Complete (LE Read Resolving List Size)

149 0.152762 host controller HCI_CMD 4 Sent LE Clear Resolving List

150 0.152881 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

151 0.154746 controller host HCI_EVT 7 Rcvd Command Complete (LE Clear Resolving List)

Best Regards,

Danny

[Chan Danny]

Hi  Matthias,

1. Just tried your latest develop branch with hid_keyboard_demo.

     Firstly I enable the log then run, but cannot pair (please see logs below)

     Then I disable the log and run to pair first, then enable log and run again, it cannot connect (please see logs below)

     By the way, how can I attach files here, not picture files?

2. Just wonder if there is some workaround. Because in my application, I need a HFP and able to send "Page up" and "Page down" keypress only. And I see there is SPP inside HFP for AT command, can I send a custom made AT command or interpret some existing AT command in PC to emulate it as Page up/down keypress, so that I don't need to merge 2 profiles together??

Connect pair:

1 0.000000 PKTLOG 31 I (214) cpu_start: Pro cpu up.

2 0.000000 PKTLOG 36 I (215) cpu_start: Single core mode

3 0.000000 PKTLOG 43 I (223) cpu_start: Pro cpu start user code

4 0.000000 PKTLOG 39 I (223) cpu_start: cpu freq: 240000000

5 0.000000 PKTLOG 44 I (223) cpu_start: Application information:

6 0.000000 PKTLOG 55 I (227) cpu_start: Project name:     hid_keyboard_demo

7 0.000000 PKTLOG 39 I (233) cpu_start: App version:      1

8 0.000000 PKTLOG 58 I (238) cpu_start: Compile time:     Sep  8 2021 21:59:21

9 0.000000 PKTLOG 57 I (244) cpu_start: ELF file SHA256:  ca949f84be4aa650...

10 0.000000 PKTLOG 69 I (250) cpu_start: ESP-IDF:          v4.4-dev-2594-ga20df743f1-dirty

11 0.000000 PKTLOG 71 I (257) heap_init: Initializing. RAM available for dynamic allocation:

12 0.000000 PKTLOG 60 I (264) heap_init: At 3FF80000 len 00002000 (8 KiB): RTCRAM

13 0.000000 PKTLOG 58 I (270) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

14 0.000000 PKTLOG 58 I (276) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM

15 0.000000 PKTLOG 59 I (282) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

16 0.000000 PKTLOG 59 I (289) heap_init: At 3FFCA0F0 len 00015F10 (87 KiB): DRAM

17 0.000000 PKTLOG 62 I (295) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM

18 0.000000 PKTLOG 59 I (301) heap_init: At 40078000 len 00008000 (32 KiB): IRAM

19 0.000000 PKTLOG 59 I (307) heap_init: At 40096E3C len 000091C4 (36 KiB): IRAM

20 0.000000 PKTLOG 37 I (314) spi_flash: detected chip: gd

21 0.000000 PKTLOG 33 I (318) spi_flash: flash io: dio

22 0.000000 PKTLOG 65 I (322) sleep: Configure to isolate all GPIO pins in sleep state

23 0.000000 PKTLOG 70 I (329) sleep: Enable automatic switching of GPIO sleep configuration

24 0.000000 PKTLOG 51 I (336) esp_core_dump_uart: Init core dump to UART

25 0.000000 PKTLOG 50 I (341) cpu_start: Starting scheduler on PRO CPU.

26 -31622399.639000 PKTLOG 55 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535

27 -31622399.639000 PKTLOG 29 HID service record size: 274

28 -31622399.639000 PKTLOG 38 Device ID SDP service record size: 64

29 -31622399.634000 PKTLOG 54 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x13 mtu 100

30 -31622399.627000 PKTLOG 54 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x11 mtu 100

31 -31622399.619000 PKTLOG 49 hci.c.3957: hci_power_control: 1, current mode 0

32 -31622399.614000 PKTLOG 27 main.c.209: transport_init

33 -31622399.610000 PKTLOG 27 main.c.225: transport_open

34 -31622399.610000 PKTLOG 59 I (395) BTDM_INIT: BT controller compile version [bfbbe1e]

35 -31622399.610000 PKTLOG 48 I (401) system_api: Base MAC address is not set

36 -31622399.610000 PKTLOG 61 I (406) system_api: read default base MAC address from EFUSE

37 -31622399.610000 PKTLOG 64 I (415) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

38 -31622399.175000 PKTLOG 34 hci.c.5439: BTSTACK_EVENT_STATE 1

39 -31622399.175000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

40 -31622399.174000 host controller HCI_CMD 4 Sent Reset

41 -31622399.170000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

42 -31622399.170000 controller host HCI_EVT 7 Rcvd Command Complete (Reset)

43 -31622399.169000 host controller HCI_CMD 4 Sent Read Local Version Information

44 -31622399.164000 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Version Information)

45 -31622399.160000 PKTLOG 33 hci.c.2227: Manufacturer: 0x0060

46 -31622399.155000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

47 -31622399.153000 host controller HCI_CMD 4 Sent Read Local Name

48 -31622399.147000 controller host HCI_EVT 64 Rcvd Command Complete (Read Local Name)[Malformed Packet]

49 -31622399.147000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

50 -31622399.147000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

51 -31622399.147000 PKTLOG 154 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

52 -31622399.081000 PKTLOG 24 hci.c.2133: local name:

53 -31622399.077000 PKTLOG 52 hci.c.1805: Received local name, need baud change 0

54 -31622399.071000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

55 -31622399.068000 host controller HCI_CMD 4 Sent Read Local Supported Commands

56 -31622399.063000 controller host HCI_EVT 64 Rcvd Command Complete (Read Local Supported Commands)[Malformed Packet]

57 -31622399.063000 PKTLOG 22 00 00 00 00 00 00 00

58 -31622399.045000 PKTLOG 53 hci.c.2245: Local supported commands summary bf - 1f

59 -31622399.038000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

60 -31622399.036000 host controller HCI_CMD 4 Sent Read BD ADDR

61 -31622399.030000 controller host HCI_EVT 13 Rcvd Command Complete (Read BD ADDR)

62 -31622399.028000 PKTLOG 65 hci.c.2188: Local Address, Status: 0x00: Addr: 98:CD:AC:D0:85:E2

63 -31622399.020000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

64 -31622399.018000 host controller HCI_CMD 4 Sent Read Buffer Size

65 -31622399.012000 controller host HCI_EVT 14 Rcvd Command Complete (Read Buffer Size)

66 -31622399.009000 PKTLOG 101 hci.c.2150: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4

67 -31622398.998000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

68 -31622398.996000 host controller HCI_CMD 4 Sent Read Local Supported Features

69 -31622398.990000 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Supported Features)

70 -31622398.987000 PKTLOG 38 hci.c.2213: Packet types cc18, eSCO 1

71 -31622398.982000 PKTLOG 43 hci.c.2216: BR/EDR support 1, LE support 1

72 -31622398.976000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

73 -31622398.974000 host controller HCI_CMD 11 Sent Host Buffer Size

74 -31622398.967000 controller host HCI_EVT 7 Rcvd Command Complete (Host Buffer Size)

75 -31622398.965000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

76 -31622398.963000 host controller HCI_CMD 5 Sent Set Host Controller To Host Flow Control

77 -31622398.957000 controller host HCI_EVT 7 Rcvd Command Complete (Set Host Controller To Host Flow Control)

78 -31622398.956000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

79 -31622398.953000 host controller HCI_CMD 12 Sent Set Event Mask

80 -31622398.946000 controller host HCI_EVT 7 Rcvd Command Complete (Set Event Mask)

81 -31622398.945000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

82 -31622398.942000 host controller HCI_CMD 5 Sent Write Simple Pairing Mode

83 -31622398.937000 controller host HCI_EVT 7 Rcvd Command Complete (Write Simple Pairing Mode)

84 -31622398.935000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

85 -31622398.933000 host controller HCI_CMD 6 Sent Write Page Timeout

86 -31622398.927000 controller host HCI_EVT 7 Rcvd Command Complete (Write Page Timeout)

87 -31622398.926000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

88 -31622398.923000 host controller HCI_CMD 6 Sent Write Default Link Policy Settings

89 -31622398.917000 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Link Policy Settings)

90 -31622398.916000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

91 -31622398.913000 host controller HCI_CMD 7 Sent Write Class of Device

92 -31622398.907000 controller host HCI_EVT 7 Rcvd Command Complete (Write Class of Device)

93 -31622398.906000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

94 -31622398.904000 host controller HCI_CMD 64 Sent Change Local Name[Malformed Packet]

95 -31622398.904000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

96 -31622398.904000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

97 -31622398.904000 PKTLOG 145 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

98 -31622398.834000 controller host HCI_EVT 7 Rcvd Command Complete (Change Local Name)

99 -31622398.832000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

100 -31622398.830000 host controller HCI_CMD 64 Sent Write Extended Inquiry Response

101 -31622398.830000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

102 -31622398.830000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

103 -31622398.830000 PKTLOG 124 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

104 -31622398.762000 controller host HCI_EVT 7 Rcvd Command Complete (Write Extended Inquiry Response)

105 -31622398.760000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

106 -31622398.758000 host controller HCI_CMD 5 Sent Write Inquiry Mode

107 -31622398.752000 controller host HCI_EVT 7 Rcvd Command Complete (Write Inquiry Mode)

108 -31622398.751000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

109 -31622398.749000 host controller HCI_CMD 5 Sent Write Secure Connections Host Support

110 -31622398.743000 controller host HCI_EVT 7 Rcvd Command Complete (Write Secure Connections Host Support)

111 -31622398.742000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

112 -31622398.739000 host controller HCI_CMD 5 Sent Write Scan Enable

113 -31622398.734000 controller host HCI_EVT 7 Rcvd Command Complete (Write Scan Enable)

114 -31622398.732000 PKTLOG 49 hci.c.5565: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1

115 -31622398.726000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

116 -31622398.723000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

117 -31622398.721000 host controller HCI_CMD 5 Sent Write SCO Flow Control Enable

118 -31622398.715000 controller host HCI_EVT 7 Rcvd Command Complete (Write SCO Flow Control Enable)

119 -31622398.714000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

120 -31622398.711000 host controller HCI_CMD 5 Sent Write Default Erroneous Data Reporting

121 -31622398.706000 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Erroneous Data Reporting)

122 -31622398.704000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

123 -31622398.702000 host controller HCI_CMD 4 Sent LE Read Buffer Size [v1]

124 -31622398.697000 controller host HCI_EVT 10 Rcvd Command Complete (LE Read Buffer Size [v1])

125 -31622398.695000 PKTLOG 56 hci.c.2170: hci_le_read_buffer_size: size 251, count 10

126 -31622398.688000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

127 -31622398.685000 host controller HCI_CMD 6 Sent Write LE Host Supported

128 -31622398.679000 controller host HCI_EVT 7 Rcvd Command Complete (Write LE Host Supported)

129 -31622398.678000 PKTLOG 34 hci.c.1913: Supported commands 30

130 -31622398.673000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

131 -31622398.671000 host controller HCI_CMD 12 Sent LE Set Event Mask

132 -31622398.664000 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Event Mask)

133 -31622398.662000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

134 -31622398.659000 host controller HCI_CMD 4 Sent LE Read Maximum Data Length

135 -31622398.654000 controller host HCI_EVT 15 Rcvd Command Complete (LE Read Maximum Data Length)

136 -31622398.651000 PKTLOG 76 hci.c.2177: hci_le_read_maximum_data_length: tx octets 251, tx time 2120 us

137 -31622398.642000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

138 -31622398.640000 host controller HCI_CMD 8 Sent LE Write Suggested Default Data Length

139 -31622398.634000 controller host HCI_EVT 7 Rcvd Command Complete (LE Write Suggested Default Data Length)

140 -31622398.632000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

141 -31622398.630000 host controller HCI_CMD 4 Sent LE Read White List Size

142 -31622398.624000 controller host HCI_EVT 8 Rcvd Command Complete (LE Read White List Size)

143 -31622398.623000 PKTLOG 49 hci.c.2183: hci_le_read_white_list_size: size 12

144 -31622398.616000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

145 -31622398.614000 host controller HCI_CMD 11 Sent LE Set Scan Parameters

146 -31622398.607000 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Parameters)

147 -31622398.605000 PKTLOG 47 hci.c.1663: hci_init_done -> HCI_STATE_WORKING

148 -31622398.600000 PKTLOG 34 hci.c.5439: BTSTACK_EVENT_STATE 2

149 -31622398.595000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

150 -31622398.592000 PKTLOG 61 main.c.346: transport: configure SCO over HCI, result 0x0000

151 -31622398.592000 PKTLOG 44 BTstack up and running at 98:CD:AC:D0:85:E2

152 -31622398.580000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

153 -31622387.825000 controller host HCI_EVT 13 Rcvd Connect Request

154 -31622387.825000 PKTLOG 59 hci.c.2659: Connection_incoming: 1C:1B:B5:69:E3:B1, type 1

155 -31622387.824000 PKTLOG 65 hci.c.203: create_connection_for_addr 1C:1B:B5:69:E3:B1, type fd

156 -31622387.816000 PKTLOG 50 hci.c.4592: sending hci_accept_connection_request

157 -31622387.810000 host controller HCI_CMD 11 Sent Accept Connection Request

158 -31622387.804000 controller host HCI_EVT 7 Rcvd Command Status (Accept Connection Request)

159 -31622387.801000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

160 -31622387.613000 controller host HCI_EVT 14 Rcvd Connect Complete

161 -31622387.612000 PKTLOG 61 hci.c.2683: Connection_complete (status=0) 1C:1B:B5:69:E3:B1

162 -31622387.611000 PKTLOG 58 hci.c.2703: New connection: handle 128, 1C:1B:B5:69:E3:B1

163 -31622387.604000 PKTLOG 51 hci.c.5508: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1

164 -31622387.597000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

165 -31622387.594000 host controller HCI_CMD 6 Sent Read Remote Supported Features

166 -31622387.591000 controller host HCI_EVT 6 Rcvd Max Slots Change

167 -31622387.588000 IntelCor_69:e3:b1 () Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) L2CAP 17 Rcvd Connection Request (SDP, SCID: 0x0040)

168 -31622387.581000 PKTLOG 58 l2cap.c.2012: create channel 0x3ffd2ca4, local_cid 0x0041

169 -31622387.574000 PKTLOG 120 l2cap.c.1090: L2CAP_EVENT_INCOMING_CONNECTION addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40

170 -31622387.562000 controller host HCI_EVT 17 Rcvd Unknown 0x%08x

171 -31622387.556000 PKTLOG 53 l2cap.c.2660: L2CAP_ACCEPT_CONNECTION local_cid 0x41

172 -31622387.549000 controller host HCI_EVT 7 Rcvd Command Status (Read Remote Supported Features)

173 -31622387.546000 controller host HCI_EVT 14 Rcvd Read Remote Supported Features

174 -31622387.540000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

175 -31622387.537000 Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) IntelCor_69:e3:b1 () L2CAP 21 Sent Connection Response - Success (SCID: 0x0040, DCID: 0x0041)

176 -31622387.530000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

177 -31622387.528000 Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) IntelCor_69:e3:b1 () L2CAP 21 Sent Configure Request (DCID: 0x0040)

178 -31622387.520000 PKTLOG 48 l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

179 -31622387.514000 PKTLOG 49 l2cap.c.1259: l2cap_start_rtx for local cid 0x41

180 -31622387.508000 controller host HCI_EVT 8 Rcvd Number of Completed Packets

181 -31622387.504000 controller host HCI_EVT 8 Rcvd Number of Completed Packets

182 -31622387.500000 IntelCor_69:e3:b1 () Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) L2CAP 21 Rcvd Configure Request (DCID: 0x0041)

183 -31622387.493000 PKTLOG 55 l2cap.c.2871: L2CAP signaling handler code 4, state 11

184 -31622387.486000 PKTLOG 30 l2cap.c.2716: Remote MTU 1024

185 -31622387.481000 IntelCor_69:e3:b1 () Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) L2CAP 23 Rcvd Configure Response - Success (SCID: 0x0041)

186 -31622387.474000 PKTLOG 55 l2cap.c.2871: L2CAP signaling handler code 5, state 11

187 -31622387.467000 PKTLOG 48 l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

188 -31622387.461000 PKTLOG 56 l2cap.c.2801: l2cap_signaling_handle_configure_response

189 -31622387.454000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

190 -31622387.451000 Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) IntelCor_69:e3:b1 () L2CAP 23 Sent Configure Response - Success (SCID: 0x0040)

191 -31622387.443000 PKTLOG 175 l2cap.c.1056: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 1C:1B:B5:69:E3:B1 handle 0x80 psm 0x1 local_cid 0x41 remote_cid 0x40 local_mtu 1691, remote_mtu 1024, flush_timeout 0

192 -31622387.426000 controller host HCI_EVT 27 Rcvd Unknown 0x%08x

193 -31622387.417000 controller host HCI_EVT 8 Rcvd Number of Completed Packets

194 -31622387.413000 controller host HCI_EVT 12 Rcvd IO Capability Response

195 -31622387.408000 PKTLOG 66 hci.c.413: pairing started, ssp 1, initiator 0, requested level 2

196 -31622387.401000 controller host HCI_EVT 13 Rcvd Unknown 0x%08x

197 -31622387.396000 controller host HCI_EVT 9 Rcvd IO Capability Request

198 -31622387.391000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

199 -31622387.389000 host controller HCI_CMD 9 Sent Host Number of Completed Packets

200 -31622387.385000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

201 -31622387.382000 host controller HCI_CMD 7 Sent Read Remote Extended Features

202 -31622387.378000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

203 -31622357.421000 controller host HCI_EVT 10 Rcvd Simple Pairing Complete

204 -31622357.420000 PKTLOG 39 hci.c.429: pairing complete, status 22

205 -31622357.420000 controller host HCI_EVT 13 Rcvd Unknown 0x%08x

206 -31622357.416000 controller host HCI_EVT 7 Rcvd Command Status (Read Remote Extended Features)

207 -31622357.339000 controller host HCI_EVT 7 Rcvd Disconnect Complete

208 -31622357.338000 PKTLOG 56 l2cap.c.1084: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x41

209 -31622357.338000 controller host HCI_EVT 5 Rcvd Unknown 0x%08x

210 -31622357.336000 PKTLOG 56 l2cap.c.2018: free channel 0x3ffd2ca4, local_cid 0x0041

211 -31622357.329000 PKTLOG 48 l2cap.c.1250: l2cap_stop_rtx for local cid 0x41

212 -31622357.323000 PKTLOG 62 hci.c.1009: Connection closed: handle 0x80, 1C:1B:B5:69:E3:B1

213 -31622357.316000 PKTLOG 51 hci.c.5508: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0

214 -31622357.309000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

Cannot connect:

1 0.000000 PKTLOG 31 I (214) cpu_start: Pro cpu up.

2 0.000000 PKTLOG 36 I (215) cpu_start: Single core mode

3 0.000000 PKTLOG 43 I (223) cpu_start: Pro cpu start user code

4 0.000000 PKTLOG 39 I (223) cpu_start: cpu freq: 240000000

5 0.000000 PKTLOG 44 I (223) cpu_start: Application information:

6 0.000000 PKTLOG 55 I (227) cpu_start: Project name:     hid_keyboard_demo

7 0.000000 PKTLOG 39 I (233) cpu_start: App version:      1

8 0.000000 PKTLOG 58 I (238) cpu_start: Compile time:     Sep  8 2021 21:59:21

9 0.000000 PKTLOG 57 I (244) cpu_start: ELF file SHA256:  ca949f84be4aa650...

10 0.000000 PKTLOG 69 I (250) cpu_start: ESP-IDF:          v4.4-dev-2594-ga20df743f1-dirty

11 0.000000 PKTLOG 71 I (257) heap_init: Initializing. RAM available for dynamic allocation:

12 0.000000 PKTLOG 60 I (264) heap_init: At 3FF80000 len 00002000 (8 KiB): RTCRAM

13 0.000000 PKTLOG 58 I (270) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

14 0.000000 PKTLOG 58 I (276) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM

15 0.000000 PKTLOG 59 I (282) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

16 0.000000 PKTLOG 59 I (289) heap_init: At 3FFCA0F0 len 00015F10 (87 KiB): DRAM

17 0.000000 PKTLOG 62 I (295) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM

18 0.000000 PKTLOG 59 I (301) heap_init: At 40078000 len 00008000 (32 KiB): IRAM

19 0.000000 PKTLOG 59 I (307) heap_init: At 40096E3C len 000091C4 (36 KiB): IRAM

20 0.000000 PKTLOG 37 I (314) spi_flash: detected chip: gd

21 0.000000 PKTLOG 33 I (318) spi_flash: flash io: dio

22 0.000000 PKTLOG 65 I (322) sleep: Configure to isolate all GPIO pins in sleep state

23 0.000000 PKTLOG 70 I (329) sleep: Enable automatic switching of GPIO sleep configuration

24 0.000000 PKTLOG 51 I (336) esp_core_dump_uart: Init core dump to UART

25 0.000000 PKTLOG 50 I (341) cpu_start: Starting scheduler on PRO CPU.

26 -31622399.639000 PKTLOG 55 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x1 mtu 65535

27 -31622399.639000 PKTLOG 29 HID service record size: 274

28 -31622399.639000 PKTLOG 38 Device ID SDP service record size: 64

29 -31622399.634000 PKTLOG 54 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x13 mtu 100

30 -31622399.627000 PKTLOG 54 l2cap.c.3893: L2CAP_REGISTER_SERVICE psm 0x11 mtu 100

31 -31622399.619000 PKTLOG 49 hci.c.3957: hci_power_control: 1, current mode 0

32 -31622399.614000 PKTLOG 27 main.c.209: transport_init

33 -31622399.610000 PKTLOG 27 main.c.225: transport_open

34 -31622399.610000 PKTLOG 59 I (395) BTDM_INIT: BT controller compile version [bfbbe1e]

35 -31622399.610000 PKTLOG 48 I (401) system_api: Base MAC address is not set

36 -31622399.610000 PKTLOG 61 I (406) system_api: read default base MAC address from EFUSE

37 -31622399.610000 PKTLOG 64 I (415) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

38 -31622399.178000 PKTLOG 34 hci.c.5439: BTSTACK_EVENT_STATE 1

39 -31622399.178000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

40 -31622399.177000 host controller HCI_CMD 4 Sent Reset

41 -31622399.176000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

42 -31622399.173000 controller host HCI_EVT 7 Rcvd Command Complete (Reset)

43 -31622399.172000 host controller HCI_CMD 4 Sent Read Local Version Information

44 -31622399.166000 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Version Information)

45 -31622399.163000 PKTLOG 33 hci.c.2227: Manufacturer: 0x0060

46 -31622399.158000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

47 -31622399.156000 host controller HCI_CMD 4 Sent Read Local Name

48 -31622399.151000 controller host HCI_EVT 64 Rcvd Command Complete (Read Local Name)[Malformed Packet]

49 -31622399.151000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

50 -31622399.151000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

51 -31622399.151000 PKTLOG 154 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

52 -31622399.084000 PKTLOG 24 hci.c.2133: local name:

53 -31622399.080000 PKTLOG 52 hci.c.1805: Received local name, need baud change 0

54 -31622399.074000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

55 -31622399.071000 host controller HCI_CMD 4 Sent Read Local Supported Commands

56 -31622399.066000 controller host HCI_EVT 64 Rcvd Command Complete (Read Local Supported Commands)[Malformed Packet]

57 -31622399.066000 PKTLOG 22 00 00 00 00 00 00 00

58 -31622399.048000 PKTLOG 53 hci.c.2245: Local supported commands summary bf - 1f

59 -31622399.041000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

60 -31622399.039000 host controller HCI_CMD 4 Sent Read BD ADDR

61 -31622399.034000 controller host HCI_EVT 13 Rcvd Command Complete (Read BD ADDR)

62 -31622399.031000 PKTLOG 65 hci.c.2188: Local Address, Status: 0x00: Addr: 98:CD:AC:D0:85:E2

63 -31622399.023000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

64 -31622399.021000 host controller HCI_CMD 4 Sent Read Buffer Size

65 -31622399.015000 controller host HCI_EVT 14 Rcvd Command Complete (Read Buffer Size)

66 -31622399.012000 PKTLOG 101 hci.c.2150: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4

67 -31622399.001000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

68 -31622398.999000 host controller HCI_CMD 4 Sent Read Local Supported Features

69 -31622398.994000 controller host HCI_EVT 15 Rcvd Command Complete (Read Local Supported Features)

70 -31622398.990000 PKTLOG 38 hci.c.2213: Packet types cc18, eSCO 1

71 -31622398.985000 PKTLOG 43 hci.c.2216: BR/EDR support 1, LE support 1

72 -31622398.979000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

73 -31622398.977000 host controller HCI_CMD 11 Sent Host Buffer Size

74 -31622398.969000 controller host HCI_EVT 7 Rcvd Command Complete (Host Buffer Size)

75 -31622398.968000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

76 -31622398.966000 host controller HCI_CMD 5 Sent Set Host Controller To Host Flow Control

77 -31622398.960000 controller host HCI_EVT 7 Rcvd Command Complete (Set Host Controller To Host Flow Control)

78 -31622398.959000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

79 -31622398.956000 host controller HCI_CMD 12 Sent Set Event Mask

80 -31622398.949000 controller host HCI_EVT 7 Rcvd Command Complete (Set Event Mask)

81 -31622398.948000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

82 -31622398.945000 host controller HCI_CMD 5 Sent Write Simple Pairing Mode

83 -31622398.939000 controller host HCI_EVT 7 Rcvd Command Complete (Write Simple Pairing Mode)

84 -31622398.938000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

85 -31622398.936000 host controller HCI_CMD 6 Sent Write Page Timeout

86 -31622398.930000 controller host HCI_EVT 7 Rcvd Command Complete (Write Page Timeout)

87 -31622398.929000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

88 -31622398.926000 host controller HCI_CMD 6 Sent Write Default Link Policy Settings

89 -31622398.921000 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Link Policy Settings)

90 -31622398.919000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

91 -31622398.916000 host controller HCI_CMD 7 Sent Write Class of Device

92 -31622398.911000 controller host HCI_EVT 7 Rcvd Command Complete (Write Class of Device)

93 -31622398.909000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

94 -31622398.907000 host controller HCI_CMD 64 Sent Change Local Name[Malformed Packet]

95 -31622398.907000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

96 -31622398.907000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

97 -31622398.907000 PKTLOG 145 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

98 -31622398.837000 controller host HCI_EVT 7 Rcvd Command Complete (Change Local Name)

99 -31622398.835000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

100 -31622398.833000 host controller HCI_CMD 64 Sent Write Extended Inquiry Response

101 -31622398.833000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

102 -31622398.833000 PKTLOG 211 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

103 -31622398.833000 PKTLOG 124 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

104 -31622398.765000 controller host HCI_EVT 7 Rcvd Command Complete (Write Extended Inquiry Response)

105 -31622398.763000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

106 -31622398.761000 host controller HCI_CMD 5 Sent Write Inquiry Mode

107 -31622398.756000 controller host HCI_EVT 7 Rcvd Command Complete (Write Inquiry Mode)

108 -31622398.754000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

109 -31622398.752000 host controller HCI_CMD 5 Sent Write Secure Connections Host Support

110 -31622398.746000 controller host HCI_EVT 7 Rcvd Command Complete (Write Secure Connections Host Support)

111 -31622398.745000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

112 -31622398.742000 host controller HCI_CMD 5 Sent Write Scan Enable

113 -31622398.737000 controller host HCI_EVT 7 Rcvd Command Complete (Write Scan Enable)

114 -31622398.735000 PKTLOG 49 hci.c.5565: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1

115 -31622398.729000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

116 -31622398.726000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

117 -31622398.724000 host controller HCI_CMD 5 Sent Write SCO Flow Control Enable

118 -31622398.718000 controller host HCI_EVT 7 Rcvd Command Complete (Write SCO Flow Control Enable)

119 -31622398.717000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

120 -31622398.714000 host controller HCI_CMD 5 Sent Write Default Erroneous Data Reporting

121 -31622398.709000 controller host HCI_EVT 7 Rcvd Command Complete (Write Default Erroneous Data Reporting)

122 -31622398.707000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

123 -31622398.705000 host controller HCI_CMD 4 Sent LE Read Buffer Size [v1]

124 -31622398.700000 controller host HCI_EVT 10 Rcvd Command Complete (LE Read Buffer Size [v1])

125 -31622398.698000 PKTLOG 56 hci.c.2170: hci_le_read_buffer_size: size 251, count 10

126 -31622398.691000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

127 -31622398.688000 host controller HCI_CMD 6 Sent Write LE Host Supported

128 -31622398.682000 controller host HCI_EVT 7 Rcvd Command Complete (Write LE Host Supported)

129 -31622398.681000 PKTLOG 34 hci.c.1913: Supported commands 30

130 -31622398.676000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

131 -31622398.674000 host controller HCI_CMD 12 Sent LE Set Event Mask

132 -31622398.666000 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Event Mask)

133 -31622398.665000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

134 -31622398.662000 host controller HCI_CMD 4 Sent LE Read Maximum Data Length

135 -31622398.657000 controller host HCI_EVT 15 Rcvd Command Complete (LE Read Maximum Data Length)

136 -31622398.654000 PKTLOG 76 hci.c.2177: hci_le_read_maximum_data_length: tx octets 251, tx time 2120 us

137 -31622398.645000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

138 -31622398.643000 host controller HCI_CMD 8 Sent LE Write Suggested Default Data Length

139 -31622398.636000 controller host HCI_EVT 7 Rcvd Command Complete (LE Write Suggested Default Data Length)

140 -31622398.635000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

141 -31622398.633000 host controller HCI_CMD 4 Sent LE Read White List Size

142 -31622398.627000 controller host HCI_EVT 8 Rcvd Command Complete (LE Read White List Size)

143 -31622398.626000 PKTLOG 49 hci.c.2183: hci_le_read_white_list_size: size 12

144 -31622398.619000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

145 -31622398.617000 host controller HCI_CMD 11 Sent LE Set Scan Parameters

146 -31622398.610000 controller host HCI_EVT 7 Rcvd Command Complete (LE Set Scan Parameters)

147 -31622398.608000 PKTLOG 47 hci.c.1663: hci_init_done -> HCI_STATE_WORKING

148 -31622398.603000 PKTLOG 34 hci.c.5439: BTSTACK_EVENT_STATE 2

149 -31622398.598000 controller host HCI_EVT 4 Rcvd Unknown 0x%08x

150 -31622398.595000 PKTLOG 61 main.c.346: transport: configure SCO over HCI, result 0x0000

151 -31622398.595000 PKTLOG 44 BTstack up and running at 98:CD:AC:D0:85:E2

152 -31622398.583000 controller host HCI_EVT 3 Rcvd Unknown 0x%08x

Thanks!

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

If you use an old-school email app like Apple Mail, Thunderbird, you can attach .pklg directly. I would assume that you can attach anything with a web mailer like Gmail. Anyway, you can try to zip the .pklg and that should work with all variants. Alternatively, you can upload it somewhere and just post a link here.

HFP uses SPP/RFCOMM under the hood, but short of hacking your PC, I cannot imagine that there's an API in Windows to get access to the received AT commands.

Again, I don't think that your issues are related to the combination of HFP + HID, instead there's a pairing issue and maybe something other problem with your headset. Let's check the pairing issue and then continue from there.

Best
Matthias

> On 8 Sep 2021, at 18:25, Chan Danny <dannychan...@gmail.com> wrote:
>
> Hi Matthias,

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/da51d3ab-75ec-4eaa-9706-16859f2880fen%40googlegroups.com.

[Chan Danny]

Hi Matthias,

OK. Thanks!

Can you read my previous post, I try the desktop platform with USB dongle, but I also encounter issues (with logs posted), do you have ideas?

Best Regards,

Danny 

[Matthias Ringwald]

H Danny

Yes, I've seen the mail, but I cannot decode text traces in my head and I also cannot convert it to .pklg format to look at it with Wireshark, so I'm waiting for a .pklg file.

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/62cee67b-963e-484a-a444-93fc78bc2a75n%40googlegroups.com.

[Chan Danny]

Hi Matthias,

Oh.. I am sorry, the following are the pklg files:

1. Windows platform issue

https://www.dropbox.com/s/ug1ubrgfk94m07i/Windows.pklg?dl=0

2. hid demo cannot pair

https://www.dropbox.com/s/eskfb461en8m2ac/cannot_pair.pklg?dl=0

3. hid demo cannot connect

https://www.dropbox.com/s/jwaomrpp9nse0e9/cannot_connect.pklg?dl=0

Thanks!

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

Thanks for the logs. See below

> On 9 Sep 2021, at 10:26, Chan Danny <dannychan...@gmail.com> wrote:
>
> Hi Matthias,
>

> Oh.. I am sorry, the following are the pklg files:
>
> 1. Windows platform issue
> https://www.dropbox.com/s/ug1ubrgfk94m07i/Windows.pklg?dl=0

This looks like you've converted the textual dump from Wireshark again. Apart from that, there's no incoming or outgoing Bluetooth connection. Can you see the demo from another device?

>
> 2. hid demo cannot pair
> https://www.dropbox.com/s/eskfb461en8m2ac/cannot_pair.pklg?dl=0

The code change did not fix the issue. We will try to come up with a better fix to get this working.

>
> 3. hid demo cannot connect
> https://www.dropbox.com/s/jwaomrpp9nse0e9/cannot_connect.pklg?dl=0
>

Similar to the 1. there's no incoming or outgoing Bluetooth connection. Can you see the demo from another device?

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/62f576f0-9e47-49f7-ad13-5ebd597ab258n%40googlegroups.com.

[Chan Danny]

Hi Matthias,

1. 

Sorry, resend Logs of windows issue:

https://www.dropbox.com/s/vw1l83bewtas8f9/winusb.pklg?dl=0

You mean the demo running on the PC can be discovered by other PC? No, cannot be discovered by any device. 

Or you mean try to run on another PC? OK, I will try.

3.

The demo can be discovered and paired. It is run using limited discovery mode, so I type on the console to make it connect out, but the address it connects out is not the PC BT address.

I think the PC BT address should be stored when the device is up and communicate with PC, right?

By the way, can I run in NOT limited discovery mode??I want the device can be connected to the PC automatically.

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

In the new winusb logs, there are errors like this
Sep 08 06:24:14.910 Note hci_transport_h2_winusb.c.539: usb_process_acl_in: error reading RECV

This seems to be a problem of the stack communicating with your USB Bluetooth Dongle on Windows. If you have, please try another Bluetooth dongle and/or another Windows machine. I'm using e.g. a cheap CSR 8510 dongle which works well. I've also tested the Winusb version with that one.

I'll get back to you when we have an update to the ESP32 pairing problem and can continue from there to check first hid_keyboard and then hfp_hf_demo.

best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/01d7d632-8654-4587-a56b-0be821a8dfcbn%40googlegroups.com.

[Matthias Ringwald]

Hi Danny

We've made another change to the pairing logic that might fix the pairing issue you get with the ESP32. Please update to the latest version of develop branch and retest the hfp_keyboard_demo. If that works now, please also test the hfp_hf_demo - and provide log files.

Best
Matthias

[Chan Danny]

Hi Matthias,

I tried your new branch.

For the keyboard demo, I can pair now even there is logs, but I still cannot connect, there is some error:

https://www.dropbox.com/s/qithyu91fx79xtn/Keyboard_can_pair.pklg?dl=0

Then reset the device, still cannot connect:

https://www.dropbox.com/s/oc5dl8kpgnb3msb/Keyboard_still_cannot_connect.pklg?dl=0

Then I tried the HSP demo, can pair, but no audio is transmitted, and cannot disconnect, no Service level connection released message received:

https://www.dropbox.com/s/kp5n5ekwlhmv3uj/HSP_no_audio_cannot_disconnect.pklg?dl=0

Hope can help you.

Thanks!

Best Regards,

Danny

[Chan Danny]

Hi  Matthias,

Somehow I can connect once for the keyboard demo, I can see the difference is from the Rcvd Connection Request/Rcvd Connect Request:

Can connect:

180 -31622382.612000 IntelCor_69:e3:b1 () Espressi_d0:85:e2 (HID Keyboard Demo 98:CD:AC:D0:85:E2) L2CAP 17 Rcvd Connection Request (SDP, SCID: 0x0040)

Cannot connect:

162 -31622386.685000 controller host HCI_EVT 13 Rcvd Connect Request

Here is the logs, why there is such difference?

https://www.dropbox.com/s/0ctcdylqkh62ram/Keybord_somehow_can_connect.pklg?dl=0

Then I reset the device, but then cannot connect again, just pair:

https://www.dropbox.com/s/58pbyy0m9makf2m/Keyboard_restart_device_cannot_connect.pklg?dl=0

Best Regards,

Danny

[Chan Danny]

Hi Matthias,

I can see there is a disconnection request(SDP), and then connection request(HID) when working.

When not working, no disconnection request(SDP) received, but connect request again and receive error of connection complete with error 0x10.

Best Regards,

Danny

[Chan Danny]

Hi Matthias,

Comparing the working and not working keyboard logs, for the not working one, after the device sent "Sent Service Search Attribute Response (fragment)[Malformed Packet]" to the PC, then the PC stop sending further SDP requests, but the working one will keep sending information request, service search request and so on...

But I don't know how to trace why it is like this....

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

Thanks for the logs. The new keyboard pairing starts good - the change fixed the pairing deadlock, which is great.

Then, there's an incoming connection from the device you are currently connected to, This cannot happen and there should be a HCI Disconnect Event before this.
My guess is that the process to copy the ESP32 console output and convert it into a packet log isn't working 100%. In the start there are comments where a part of a previous event is dumped as text.
E.g. like this:

Jan 01 04:00:00.854 HCI Command [0C14] Read Local Name SEND
Jan 01 04:00:00.859 HCI Event Command Complete [0C14] - Read Local Name - Local Name: RECV
Jan 01 04:00:00.859 Note 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 RECV

The last "Note 00:.." might have been caused by a newline in the text log. Please make sure there's one line per LOG / CMD / EVT / ACL before converting it. I can then check that again.

Later in that log, there's an outgoing L2CAP Request for HID Control which fails - the actual response is missing in the log. A new/fixed log might help here. What device do you connect to?
I won't comment on your other emails to keep the focus.

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/e888453d-443c-4241-87be-e949cc3707dan%40googlegroups.com.

[Chan Danny]

Hi Matthias,

Thanks for your reply.

Oh yes, there are some logs which are very long that breaks up into several lines, but there are no missing logs. I corrected and please check below. 

For your last question, it should be clicking on the console to make a connection from my device to PC.

1. For the keyboard demo, I can pair now even there is logs, but I still cannot connect, there is some error:

https://www.dropbox.com/s/jyvzfazlodiiipq/Keyboard_can_pair%28updated%29.pklg?dl=0

2. Sometimes I can connect for the keyboard demo, you can compare with the previous one:

https://www.dropbox.com/s/h7lh8mf0gkcc8sx/Keyboard_somehow_can_connect%28updated%29.pklg?dl=0

(After sending  Service Search Attribute Response to PC, then PC stop sending further commands in the SDP process)

3. Reset the device, just can pair and will not connect:

https://www.dropbox.com/s/pyfipekk5z1yhop/Keyboard_still_cannot_connect%28updated%29.pklg?dl=0

4. I tried the HSP demo, sometimes can pair, but no audio is transmitted, and cannot disconnect. Sometimes can connect.

https://www.dropbox.com/s/xte6c1u6mh90u2s/HSP_no_audio_cannot_disconnect%28updated%29.pklg?dl=0

https://www.dropbox.com/s/tlxe6shjagw62yc/HSP_audio_connect%28updated%29.pklg?dl=0

Best Regards,

Danny

[Chan Danny]

Hi Matthias,

Do you have any news? Thank you!

Best Regards,

Danny

[Matthias Ringwald]

Hi Danny

Thanks for the new logs. I'm not sure what's going on. I still suggest to get a CSR or Broadcom/Cypress USB Bluetooth dongle to get a first version working.

In your first keyboard log, there's an incoming connection, pairing is successful and the remote device asks for our services, which we respond to with the full SDP Service record in packet #245 if you open the log in Wireshark.
Then in packet #249, only 3 seconds later, there's an incoming connection request from the device that we're already connected to. That should not happen. I would expect a 'HCI Disconnect Complete' before a new connection request.
What's the remote device?

Then, in the log, you press a key and an outgoing connection is established and encrypted. BTstack sends an L2CAP Create Connection for HID Control but there's no response to it.

In the second log, all looks good. Have you been able to type in there? The log stops after the first HID command was received.

In the third log, the address for the outgoing device is different and you get a page timeout (no device with that address).

Best
Matthias

> To view this discussion on the web visit https://groups.google.com/d/msgid/btstack-dev/f513d8ab-5b62-47b5-977e-5e3cd2b5fb2fn%40googlegroups.com.