espressif / esp-nimble

A fork of NimBLE stack, for use with ESP32 and ESP-IDF
Apache License 2.0
79 stars 51 forks source link

Crash on BLE re-connect with iOS #46

Closed mgagic closed 2 years ago

mgagic commented 2 years ago

Hi,

I am working on a project that uses an esp32-wroom-32d as a communication module in a bigger system. It is using esp-idf v3.3.4 (it cannot be updated at the moment). I have already checked related issues (notably #8) and the fixes are already included in the version that we have. Still, there are some issues and they happen with iOS only. We have a dedicated app (developed with flutter) that's used with the device, but the crash occurs with nRF Connect as well.

When first connection is established, it is successful; one of the subsequent connections cause the crash. Sometimes, the crash won't be caused by the first subsequent connection. But if phone's BT is turned off and on, and the device hasn't been removed from the saved deviced in between, the next connection will crash the device.

The crash seems to happen after a failed assert: assertion "ble_hs_hci_ack == ((void *)0)" failed: file "esp-idf/components/nimble/nimble/nimble/host/src/ble_hs_hci.c", line 370, function: ble_hs_hci_rx_ack but it's not always in the same function assertion "ble_hs_hci_ack == ((void *)0)" failed: file "esp-idf/components/nimble/nimble/nimble/host/src/ble_hs_hci.c", line 313, function: ble_hs_hci_cmd_tx

logs: 1st try - success:

D (43500) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (43500) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (43500) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (43500) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (43510) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (43510) BLE_SRV NIMBLE:  peer_ota_addr_type=1 peer_ota_addr=
D (43520) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (43520) BLE_SRV NIMBLE:  peer_id_addr_type=1 peer_id_addr=
D (43530) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (43530) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

I (43580) BLE_SRV NIMBLE: CON HANDLER 0 
D (43830) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=531 
D (43830) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (43830) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (43830) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (43840) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (43840) BLE_SRV NIMBLE:  peer_ota_addr_type=1 peer_ota_addr=
D (43850) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (43850) BLE_SRV NIMBLE:  peer_id_addr_type=1 peer_id_addr=
D (43860) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (43860) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (43870) BLE_SRV NIMBLE: bleprph_gap_event:542 

I (43910) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 0 (max 9)

2nd try (same lifecycle) - crash:

D (50790) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (50790) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (50790) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (50800) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (50800) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (50810) BLE_SRV NIMBLE:  peer_ota_addr_type=1 peer_ota_addr=
D (50810) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (50820) BLE_SRV NIMBLE:  peer_id_addr_type=1 peer_id_addr=
D (50820) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (50830) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

I (50870) BLE_SRV NIMBLE: CON HANDLER 0 
D (52880) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 
D (52880) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (52880) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (52880) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (52890) BLE_SRV NIMBLE: ac:67:b2:c5:69:5e
D (52890) BLE_SRV NIMBLE:  peer_ota_addr_type=1 peer_ota_addr=
D (52900) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (52900) BLE_SRV NIMBLE:  peer_id_addr_type=1 peer_id_addr=
D (52910) BLE_SRV NIMBLE: 68:7d:5b:02:83:03
D (52910) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (52920) BLE_SRV NIMBLE: bleprph_gap_event:542 

I (52960) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 0 (max 9)
assertion "ble_hs_hci_ack == ((void *)0)" failed: file "esp-idf/components/nimble/nimble/nimble/host/src/ble_hs_hci.c", line 313, function: ble_hs_hci_cmd_tx
abort() was called at PC 0x401009d3 on core 1

ELF file SHA256: 9b71f13a9bb958ee

Backtrace: 0x4008eb84:0x3ffdd970 0x4008edcd:0x3ffdd990 0x401009d3:0x3ffdd9b0 0x40184f6d:0x3ffdd9e0 0x40184fe1:0x3ffdda20 0x40181397:0x3ffdda40 0x401813f3:0x3ffdda80 0x401334c6:0x3ffddac0 0x40133a0f:0x3ffddbc0 0x401806d4:0x3ffddc40 0x40181831:0x3ffddc60 0x401818ae:0x3ffddcc0 0x4017c60a:0x3ffddce0 0x4017c637:0x3ffddd00 0x4018984a:0x3ffddd20 0x401333b2:0x3ffddd40 0x40090872:0x3ffddd60

Rebooting...
ets Jun  8 2016 00:22:57

backtrace:

0x4008eb84: invoke_abort at esp-idf/components/esp32/panic.c:715
0x4008edcd: abort at /esp-idf/components/esp32/panic.c:715
0x401009d3: __assert_func at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/assert.c:63 (discriminator 8)
0x40184f6d: ble_hs_hci_cmd_tx at esp-idf/components/nimble/nimble/nimble/host/src/ble_hs_hci.c:612
0x40184fe1: ble_hs_hci_cmd_tx_empty_ack at esp-idf/components/nimble/nimble/nimble/host/src/ble_hs_hci.c:612
0x40181397: ble_gap_adv_set_data at esp-idf/components/nimble/nimble/nimble/host/src/ble_gap.c:4632
0x401813f3: ble_gap_adv_set_fields at esp-idf/components/nimble/nimble/nimble/host/src/ble_gap.c:4632
0x401334c6: bleprph_advertise at com-module/components/nimble/ble_server.c:714
0x40133a0f: bleprph_gap_event at com-module/components/nimble/ble_server.c:714
0x401806d4: ble_gap_call_event_cb at esp-idf/components/nimble/nimble/nimble/host/src/ble_gap.c:4632
0x40181831: ble_gap_conn_broken at esp-idf/components/nimble/nimble/nimble/host/src/ble_gap.c:4632
0x401818ae: ble_gap_reset_state at esp-idf/components/nimble/nimble/nimble/host/src/ble_gap.c:4632
0x4017c60a: ble_hs_reset at esp-idf/components/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:109
0x4017c637: ble_hs_event_reset at esp-idf/components/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:109
0x4018984a: ble_npl_event_run at esp-idf/components/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:121
 (inlined by) nimble_port_run at esp-idf/components/nimble/nimble/porting/nimble/src/nimble_port.c:82
0x401333b2: bleprph_host_task at com-module/components/nimble/ble_server.c:714
0x40090872: vPortTaskWrapper at esp-idf/components/freertos/port.c:403

In this specific test case, I see that device constantly shows number of stored bondings: 0, this isn't always the case so I'm not sure what happens here. But usually, it will have the phone's data stored and it will show the number of previous bonds.

our setup:

ble_hs_cfg.reset_cb = bleprph_on_reset;
ble_hs_cfg.sync_cb = bleprph_on_sync;
ble_hs_cfg.gatts_register_cb = gatt_svr_register_cb;
ble_hs_cfg.store_status_cb = ble_store_util_status_rr;
ble_hs_cfg.sm_bonding = 1;
ble_hs_cfg.sm_our_key_dist = BLE_SM_PAIR_KEY_DIST_ENC | BLE_SM_PAIR_KEY_DIST_ID;
ble_hs_cfg.sm_their_key_dist = BLE_SM_PAIR_KEY_DIST_ENC | BLE_SM_PAIR_KEY_DIST_ID;
ble_hs_cfg.sm_sc = 0;
ble_hs_cfg.sm_io_cap = BLE_HS_IO_DISPLAY_ONLY;

ble_att_set_preferred_mtu(527);

bleprph_on_sync

static void bleprph_on_sync(void)
{
    int rc;

    rc = ble_hs_util_ensure_addr(0);
    assert(rc == 0);

    /* Configure RPA */
    s_own_addr_type = BLE_OWN_ADDR_PUBLIC;
    /* Refer
     * components/bt/host/nimble/nimble/nimble/host/include/host/ble_hs_pvcy.h
     * */
    rc = ble_hs_pvcy_rpa_config(0);
    if (rc != 0) {
        ESP_LOGI(TAG, "Error configuring privacy (RPA)");
    }

    /* Printing ADDR */
    uint8_t addr_val[6] = { 0 };
    ble_hs_id_copy_addr(s_own_addr_type, addr_val, NULL);

    ESP_LOGD(TAG, "Device Address: ");
    ESP_LOG_BUFFER_HEX_LEVEL(TAG, addr_val, sizeof(addr_val), ESP_LOG_DEBUG);
    print_addr(addr_val);
    ESP_LOGD(TAG, "\n");
    /* Begin advertising. */
    bleprph_advertise();
}

menuconfig settings for Nimble image

I can provide the logs with NimBLE logging set to DEBUG, but since this already seems like a lot of information, I'm not attaching them right away.

Can anyone help with some pointers - what could be the issue? what should I check/setup differently? Let me know if I should provide any additional information.

mgagic commented 2 years ago

Additional logs with NimBLE logs set to debug:

successful case (which was second or third successful attempt after paiting)

I (198331) BLE_SRV NIMBLE: CON HANDLER 0 
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2
0x16 0x20 0x02 0x00 0x00 
Command Status: status=0 cmd_pkts=5 ocf=0x16 ogf=0x8
LE LTK Req. handle=0 rand=e8ef07f9c4c89a08 encdiv=16455
looking up our sec; peer_addr_type=0 peer_addr=0x3f 0x0e 0x5b 0xe3 0xdb 0xf4  ediv=0x4047 rand=0xe8ef07f9c4c89a08 
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18
0x1a 0x20 0x12 0x00 0x00 0x45 0x8c 0xec 0xed 0xaf 0x4d 0x4a 0x4a 0xa0 0x45 0x17 0xbf 0xa0 0x81 0x4b 0xb8 
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x1a status=0 handle=0
Encrypt change: status=0 handle=0 state=1
D (198551) BLE_SRV NIMBLE: bleprph_gap_event:584 ENC_CHANGE_EVENT
D (198551) BLE_SRV NIMBLE: bleprph_gap_event:593 subscribe event; conn_handle=0 attr_handle=8 reason=3 prev_notify=0 cur_notify=0 prev_indicate=0 cur_indicate=1

unsuccessful case after that, in the same life-cycle:

I (238551) BLE_SRV NIMBLE: CON HANDLER 0 
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2
0x16 0x20 0x02 0x00 0x00 
LE LTK Req. handle=0 rand=e8ef07f9c4c89a08 encdiv=16455
looking up our sec; peer_addr_type=0 peer_addr=0x3f 0x0e 0x5b 0xe3 0xdb 0xf4  ediv=0x4047 rand=0xe8ef07f9c4c89a08 
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18
0x1a 0x20 0x12 0x00 0x00 0x45 0x8c 0xec 0xed 0xaf 0x4d 0x4a 0x4a 0xa0 0x45 0x17 0xbf 0xa0 0x81 0x4b 0xb8 
Command complete: cmd_pkts=4 ogf=0x8 ocf=0x1a status=0 handle=0
D (240591) BLE_SRV NIMBLE: bleprph_gap_event:584 ENC_CHANGE_EVENT
D (240601) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 

It seems like after commands ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2 - LE Read Remote Features command ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18 - LE Long Term Key Request Reply command ENC_CHANGE_EVENT happens in both cases, but after that instead of a subscribe event, there is a disconnect

rahult-github commented 2 years ago

Hi @mgagic , IDF ver 3.3 is EOL now. https://www.espressif.com/en/support/documents/advisories . So, there would not be further release /fixes on this branch. I suggest to check if you can move to later version ( as nimble too has been updated a lot since 3.3 )

mgagic commented 2 years ago

Yeah, I figured as much, thanks @rahult-github. We were hoping for a quick fix until we're ready to update, but it's better to do it asap anyway. I'll close the issue for now and reopen if it's still present after the update.

mgagic commented 2 years ago

It seems like the issue is solved with the switch to esp-idf v4.4.1. On occasions when the crash would previously occur, pairing pin is requested again, but then everything continues without problems.

mgagic commented 2 years ago

Need to reopen after all.

We switched to esp-idf v4.4.1 nimble @ 1dc1ec6

We still occasionally see both causes of the crash:

I (260228) NimBLE: GAP procedure initiated: advertise; 
I (260238) NimBLE: disc_mode=2
I (260238) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (260248) NimBLE: 

D (260258) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15

D (260258) NimBLE: 0x06 
D (260258) NimBLE: 0x20 
D (260268) NimBLE: 0x0f 
D (260268) NimBLE: 0x30 
D (260268) NimBLE: 0x00 
D (260278) NimBLE: 0x60 
D (260278) NimBLE: 0x00 
D (260278) NimBLE: 0x00 
D (260278) NimBLE: 0x00 
D (260288) NimBLE: 0x00 
D (260288) NimBLE: 0x00 
D (260288) NimBLE: 0x00 
D (260288) NimBLE: 0x00 
D (260298) NimBLE: 0x00 
D (260298) NimBLE: 0x00 
D (260298) NimBLE: 0x00 
D (260298) NimBLE: 0x07 
D (260308) NimBLE: 0x00 
D (260308) NimBLE: 

D (260308) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1

D (260318) NimBLE: 0x0a 
D (260318) NimBLE: 0x20 
D (260318) NimBLE: 0x01 
D (260328) NimBLE: 0x01 
D (260328) NimBLE: 

D (264458) NimBLE: 0xae 
D (264458) NimBLE: 0xed 
D (264458) NimBLE: 0x36 
D (264458) NimBLE: 0x1d 
D (264458) NimBLE: 0x39 
D (264468) NimBLE: 0x61 
D (264468) NimBLE: 
D (264468) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (264478) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (264478) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (264488) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (264488) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (264498) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (264498) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (264508) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (264508) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (264518) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (264558) APPLIANCE_GSC_SYSTEM_STATE: appliance_set_system_state:38 Changed current system state to SYS_QUICKCONNECT(9)
I (264568) BLE_SRV NIMBLE: CON HANDLER 0 
D (264568) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2

D (264578) NimBLE: 0x16 
D (264578) NimBLE: 0x20 
D (264578) NimBLE: 0x02 
D (264588) NimBLE: 0x00 
D (264588) NimBLE: 0x00 
D (264588) NimBLE: 

D (266598) NimBLE: looking up our sec; 
D (266598) NimBLE: peer_addr_type=0 peer_addr=
D (266598) NimBLE: 0x3f 
D (266598) NimBLE: 0x0e 
D (266598) NimBLE: 0x5b 
D (266598) NimBLE: 0xe3 
D (266598) NimBLE: 0xdb 
D (266608) NimBLE: 0xf4 
D (266608) NimBLE:  
D (266608) NimBLE: ediv=0x34a1 rand=0xc03a0b2c7216aba2 
D (266618) NimBLE: 

D (266618) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18

D (266628) NimBLE: 0x1a 
D (266628) NimBLE: 0x20 
D (266628) NimBLE: 0x12 
D (266628) NimBLE: 0x00
D (266638) NimBLE: 0x00 
D (266638) NimBLE: 0x04 
D (266638) NimBLE: 0x71 
D (266638) NimBLE: 0x42 
D (266648) NimBLE: 0x5c 
D (266648) NimBLE: 0xf6 
D (266648) NimBLE: 0xba 
D (266648) NimBLE: 0x70 
D (266658) NimBLE: 0x66 
D (266658) NimBLE: 0x8e 
D (266658) NimBLE: 0x90 
D (266658) NimBLE: 0x95 
D (266668) NimBLE: 0xe9 
D (266668) NimBLE: 0x04 
D (266668) NimBLE: 0x53 
D (266668) NimBLE: 0x1b 
D (266678) NimBLE: 0x13 
D (266678) NimBLE: 

D (266678) BLE_SRV NIMBLE: bleprph_gap_event:584 ENC_CHANGE_EVENT
D (266688) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 
D (266698) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (266698) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (266708) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (266708) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (266718) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (266718) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (266728) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (266728) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (266738) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (266748) BLE_SRV NIMBLE: bleprph_gap_event:542 

D (266768) APPLIANCE_GSC_SYSTEM_STATE: appliance_clear_system_state:48 Restored current system state to SYS_INTEGRATED(8)
D (266778) NimBLE: looking up peer sec; 
D (266788) NimBLE: 

D (266788) NimBLE: looking up peer sec;

D (266788) NimBLE: 

I (266798) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 1 (max 9)

assert failed: ble_hs_hci_cmd_tx ble_hs_hci.c:301 (ble_hs_hci_ack == ((void *)0))

Backtrace:0x40081c66:0x3ffdf7500x400916f9:0x3ffdf770 0x4009886d:0x3ffdf790 0x4010dc62:0x3ffdf8b0 0x40109c2a:0x3ffdf8e0 0x40109cb9:0x3ffdf920 0x400f730b:0x3ffdf960 0x400f78ce:0x3ffdfa60 0x40108ec0:0x3ffdfae0 0x4010a151:0x3ffdfb00 0x4010a1d6:0x3ffdfb60 0x40104aba:0x3ffdfb80 0x40104ae7:0x3ffdfba0 0x4011232a:0x3ffdfbc0 0x400f71ee:0x3ffdfbe0 0x40094e31:0x3ffdfc00 
0x40081c66: panic_abort at esp-idf/components/esp_system/panic.c:402

0x400916f9: esp_system_abort at esp-idf/components/esp_system/esp_system.c:128

0x4009886d: __assert_func at esp-idf/components/newlib/assert.c:85

0x4010dc62: ble_hs_hci_cmd_tx at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci.c:301 (discriminator 1)

0x40109c2a: ble_gap_adv_set_data at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:2679

0x40109cb9: ble_gap_adv_set_fields at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:2730

0x400f730b: bleprph_advertise at com-module/build/../components/nimble/ble_server.c:414

0x400f78ce: bleprph_gap_event at /home/mgagic/Documents/br1-commodule-new/com-module/build/../components/nimble/ble_server.c:567

0x40108ec0: ble_gap_call_event_cb at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:716

0x4010a151: ble_gap_conn_broken at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1253

0x4010a1d6: ble_gap_reset_state at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1403

0x40104aba: ble_hs_reset at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:390

0x40104ae7: ble_hs_event_reset at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:538

0x4011232a: ble_npl_event_run at esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:125
 (inlined by) nimble_port_run at /home/mgagic/Documents/br1-commodule-new/esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:78

0x400f71ee: bleprph_host_task at /com-module/build/../components/nimble/ble_server.c:700

0x40094e31: vPortTaskWrapper at esp-idf/components/freertos/port/xtensa/port.c:131

and the second:

I (223809) NimBLE: GAP procedure initiated: advertise; 
I (223819) NimBLE: disc_mode=2
I (223819) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (223829) NimBLE: 

D (223829) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15

D (223839) NimBLE: 0x06 
D (223839) NimBLE: 0x20 
D (223849) NimBLE: 0x0f 
D (223849) NimBLE: 0x30 
D (223849) NimBLE: 0x00 
D (223849) NimBLE: 0x60 
D (223859) NimBLE: 0x00 
D (223859) NimBLE: 0x00 
D (223859) NimBLE: 0x00 
D (223859) NimBLE: 0x00 
D (223869) NimBLE: 0x00 
D (223869) NimBLE: 0x00 
D (223869) NimBLE: 0x00 
D (223869) NimBLE: 0x00 
D (223879) NimBLE: 0x00 
D (223879) NimBLE: 0x00 
D (223879) NimBLE: 0x07 
D (223889) NimBLE: 0x00 
D (223889) NimBLE: 

D (223889) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1

D (223899) NimBLE: 0x0a 
D (223899) NimBLE: 0x20 
D (223899) NimBLE: 0x01 
D (223899) NimBLE: 0x01 
D (223909) NimBLE: 

D (225609) NimBLE: 0x0f 
D (225609) NimBLE: 0x8c 
D (225609) NimBLE: 0x43 
D (225609) NimBLE: 0x9e 
D (225609) NimBLE: 0x3d 
D (225609) NimBLE: 0x75 
D (225609) NimBLE: 

D (225609) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (225619) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (225629) BLE_SRV NIMBLE: ac:67:b2:4a:9c:9e
D (225629) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (225639) BLE_SRV NIMBLE: ac:67:b2:4a:9c:9e
D (225639) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (225649) BLE_SRV NIMBLE: 4c:79:75:47:0e:24
D (225649) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (225659) BLE_SRV NIMBLE: 4c:79:75:47:0e:24
D (225659) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (225699) APPLIANCE_GSC_SYSTEM_STATE: appliance_set_system_state:38 Changed current system state to SYS_QUICKCONNECT(9)
I (225709) BLE_SRV NIMBLE: CON HANDLER 0 
D (225719) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2

D (225719) NimBLE: 0x16 
D (225719) NimBLE: 0x20 
D (225729) NimBLE: 0x02 
D (225729) NimBLE: 0x00 
D (225729) NimBLE: 0x00 
D (225729) NimBLE: 

D (227749) NimBLE: looking up our sec; 
D (227749) NimBLE: peer_addr_type=0 peer_addr=
D (227749) NimBLE: 0x24 
D (227749) NimBLE: 0x0e 
D (227749) NimBLE: 0x47 
D (227749) NimBLE: 0x75 
D (227749) NimBLE: 0x79 
D (227759) NimBLE: 0x4c 
D (227759) NimBLE:  
D (227759) NimBLE: ediv=0xa82 rand=0x4288cdae3b18336b 
D (227769) NimBLE: 

D (227769) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18

D (227779) NimBLE: 0x1a 
D (227779) NimBLE: 0x20 
D (227779) NimBLE: 0x12 
D (227779) NimBLE: 0x00 
D (227789) NimBLE: 0x00 
D (227789) NimBLE: 0x01 
D (227789) NimBLE: 0x1a 
D (227789) NimBLE: 0xa5 
D (227799) NimBLE: 0x61 
D (227799) NimBLE: 0x17 
D (227799) NimBLE: 0x73 
D (227799) NimBLE: 0x93 
D (227809) NimBLE: 0x96 
D (227809) NimBLE: 0x18 
D (227809) NimBLE: 0x51 
D (227809) NimBLE: 0xf8 
D (227819) NimBLE: 0x61 
D (227819) NimBLE: 0xdc 
D (227819) NimBLE: 0x8b 
D (227819) NimBLE: 0x10 
D (227829) NimBLE: 0x78 
D (227829) NimBLE: 

D (227829) BLE_SRV NIMBLE: bleprph_gap_event:584 ENC_CHANGE_EVENT
D (227839) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 
D (227849) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (227849) BLE_SRV NIMBLE: ac:67:b2:4a:9c:9e
D (227859) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (227859) BLE_SRV NIMBLE: ac:67:b2:4a:9c:9e
D (227869) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (227869) BLE_SRV NIMBLE: 4c:79:75:47:0e:24
D (227879) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (227879) BLE_SRV NIMBLE: 4c:79:75:47:0e:24
D (227889) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (227899) BLE_SRV NIMBLE: bleprph_gap_event:542 

D (227919) APPLIANCE_GSC_SYSTEM_STATE: appliance_clear_system_state:48 Restored current system state to SYS_INTEGRATED(8)
D (227929) NimBLE: looking up peer sec; 
D (227939) NimBLE: 

D (227939) NimBLE: looking up peer sec; 
D (227939) NimBLE: 

D (227949) NimBLE: looking up peer sec; 
D (227949) NimBLE: 

D (227949) NimBLE: looking up peer sec; 
D (227959) NimBLE: 

I (227959) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 3 (max 9)
E (227969) BLE_SRV NIMBLE: bleprph_advertise:417 error setting advertisement data; rc=22

assert failed: ble_gap_master_failed ble_gap.c:1186 (0)

Backtrace:0x40081c66:0x3ffdfab00x400916f9:0x3ffdfad0 0x4009886d:0x3ffdfaf0 0x401095c3:0x3ffdfc10 0x4010a1f2:0x3ffdfc30 0x40104aba:0x3ffdfc50 0x40104ae7:0x3ffdfc70 0x4011232a:0x3ffdfc90 0x400f71ee:0x3ffdfcb0 0x40094e31:0x3ffdfcd0 

0x40081c66: panic_abort at esp-idf/components/esp_system/panic.c:402
0x4009886d: __assert_func at esp-idf/components/newlib/assert.c:85
0x401095c3: ble_gap_master_failed at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1186
0x4010a1f2: ble_gap_reset_state at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gap.c:1424
0x40104aba: ble_hs_reset at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:390
0x40104ae7: ble_hs_event_reset at esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:538
0x4011232a: ble_npl_event_run at esp-idf/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:125
 (inlined by) nimble_port_run at esp-idf/components/bt/host/nimble/nimble/porting/nimble/src/nimble_port.c:78
0x400f71ee: bleprph_host_task at com-module/build/../components/nimble/ble_server.c:700
0x40094e31: vPortTaskWrapper at esp-idf/components/freertos/port/xtensa/port.c:131
rahult-github commented 2 years ago

Hi @mgagic,

I see a probable fix commit to be not part of v4.4.1. Is it possible for you to cherry-pick this fix and see if it helps resolves ( atleast the issue 1 ) ?

For issue 2 , this crash is showing the behaviour that connection failure has happened, but somehow master's operation were already cleared. Can you possibly share the detailed steps you are performing using the bleprph example of the IDF to reproduce this issue ?

mgagic commented 2 years ago

Hi @rahult-github, thanks for your help! I tried the patch but unfortunately it didn't help, I could reproduce both crashes.

logs for the (ble_hs_hci_ack == ((void *)0)) crash (the backtrace is the same):

I (105271) NimBLE: GAP procedure initiated: advertise; 
I (105281) NimBLE: disc_mode=2
I (105281) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (105291) NimBLE: 

D (105291) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15

D (105301) NimBLE: 0x06 
D (105301) NimBLE: 0x20 
D (105311) NimBLE: 0x0f 
D (105311) NimBLE: 0x30 
D (105311) NimBLE: 0x00 
D (105311) NimBLE: 0x60 
D (105321) NimBLE: 0x00 
D (105321) NimBLE: 0x00 
D (105321) NimBLE: 0x00 
D (105321) NimBLE: 0x00 
D (105331) NimBLE: 0x00 
D (105331) NimBLE: 0x00 
D (105331) NimBLE: 0x00 
D (105331) NimBLE: 0x00 
D (105341) NimBLE: 0x00 
D (105341) NimBLE: 0x00 
D (105341) NimBLE: 0x07 
D (105341) NimBLE: 0x00 
D (105351) NimBLE: 

D (105351) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1

D (105361) NimBLE: 0x0a 
D (105361) NimBLE: 0x20 
D (105361) NimBLE: 0x01 
D (105361) NimBLE: 0x01 
D (105371) NimBLE: 

D (109181) NimBLE: 0xfd 
D (109181) NimBLE: 0x8c 
D (109181) NimBLE: 0x17 
D (109181) NimBLE: 0x03 
D (109181) NimBLE: 0xe1 
D (109181) NimBLE: 0x5e 
D (109181) NimBLE: 

D (109191) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (109191) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (109201) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (109201) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (109211) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (109211) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (109221) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (109221) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (109231) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (109231) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (109271) APPLIANCE_GSC_SYSTEM_STATE: appliance_set_system_state:38 Changed current system state to SYS_QUICKCONNECT(9)
I (109281) BLE_SRV NIMBLE: CON HANDLER 0 
D (109291) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2

D (109291) NimBLE: 0x16 
D (109301) NimBLE: 0x20 
D (109301) NimBLE: 0x02 
D (109301) NimBLE: 0x00 
D (109301) NimBLE: 0x00 
D (109311) NimBLE: 

D (111321) NimBLE: looking up our sec; 
D (111321) NimBLE: peer_addr_type=0 peer_addr=
D (111321) NimBLE: 0x3f 
D (111321) NimBLE: 0x0e 
D (111321) NimBLE: 0x5b 
D (111321) NimBLE: 0xe3 
D (111321) NimBLE: 0xdb 
D (111331) NimBLE: 0xf4 
D (111331) NimBLE:  
D (111331) NimBLE: ediv=0x2ca9 rand=0x8960fb85052e3945 
D (111341) NimBLE: 

D (111341) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18

D (111351) NimBLE: 0x1a 
D (111351) NimBLE: 0x20 
D (111351) NimBLE: 0x12 
D (111351) NimBLE: 0x00 
D (111361) NimBLE: 0x00 
D (111361) NimBLE: 0xea 
D (111361) NimBLE: 0x33 
D (111361) NimBLE: 0xd8 
D (111371) NimBLE: 0xba 
D (111371) NimBLE: 0x7c 
D (111371) NimBLE: 0x9a 
D (111371) NimBLE: 0xf7 
D (111381) NimBLE: 0xae 
D (111381) NimBLE: 0x4f 
D (111381) NimBLE: 0xe8 
D (111381) NimBLE: 0x67 
D (111391) NimBLE: 0x97 
D (111391) NimBLE: 0x47 
D (111391) NimBLE: 0x8d 
D (111391) NimBLE: 0xa0 
D (111401) NimBLE: 0xfb 
D (111401) NimBLE: 

D (111401) BLE_SRV NIMBLE: bleprph_gap_event:584 ENC_CHANGE_EVENT
D (111411) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 
D (111411) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (111421) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (111431) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (111431) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (111441) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (111441) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (111451) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (111451) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (111461) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (111471) BLE_SRV NIMBLE: bleprph_gap_event:542 

D (111491) APPLIANCE_GSC_SYSTEM_STATE: appliance_clear_system_state:48 Restored current system state to SYS_INTEGRATED(8)
D (111501) NimBLE: looking up peer sec; 
D (111511) NimBLE: 

D (111511) NimBLE: looking up peer sec; 
D (111511) NimBLE: 

I (111521) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 1 (max 9)

assert failed: ble_hs_hci_cmd_tx ble_hs_hci.c:315 (ble_hs_hci_ack == ((void *)0))

For the second one, I will try to reproduce it with the blephrph example and share the steps.

mgagic commented 2 years ago

I still don't have a crashing minimal example to share, I'm working on it, but I added additional logs to the handling of BLE_GAP_EVENT_ENC_CHANGE event and I see that the status is always 0x07 just before it crashes and encrypted/auth/bonded are 0 (in the working case, it is status is 0x00 and encrypted=1 authenticated=1 bonded=1)


I (305039) NimBLE: GAP procedure initiated: advertise; 
I (305049) NimBLE: disc_mode=2
I (305049) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (305059) NimBLE: 

D (305069) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15

D (305069) NimBLE: 0x06 
D (305069) NimBLE: 0x20 
D (305079) NimBLE: 0x0f 
D (305079) NimBLE: 0x30 
D (305079) NimBLE: 0x00 
D (305079) NimBLE: 0x60 
D (305089) NimBLE: 0x00 
D (305089) NimBLE: 0x00 
D (305089) NimBLE: 0x00 
D (305099) NimBLE: 0x00 
D (305099) NimBLE: 0x00 
D (305099) NimBLE: 0x00 
D (305099) NimBLE: 0x00 
D (305109) NimBLE: 0x00 
D (305109) NimBLE: 0x00 
D (305109) NimBLE: 0x00 
D (305109) NimBLE: 0x07 
D (305119) NimBLE: 0x00 
D (305119) NimBLE: 

D (305119) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1

D (305129) NimBLE: 0x0a 
D (305129) NimBLE: 0x20 
D (305129) NimBLE: 0x01 
D (305129) NimBLE: 0x01 
D (305139) NimBLE: 

D (310629) NimBLE: 0x12 
D (310629) NimBLE: 0xf7 
D (310629) NimBLE: 0xfb 
D (310629) NimBLE: 0xa4 
D (310629) NimBLE: 0x71 
D (310629) NimBLE: 0x44 
D (310629) NimBLE: 

D (310639) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (310639) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (310649) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (310649) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (310659) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (310659) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (310669) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (310669) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (310679) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (310679) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (310719) APPLIANCE_GSC_SYSTEM_STATE: appliance_set_system_state:38 Changed current system state to SYS_QUICKCONNECT(9)
I (310729) BLE_SRV NIMBLE: CON HANDLER 0 
D (310739) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2

D (310739) NimBLE: 0x16 
D (310749) NimBLE: 0x20 
D (310749) NimBLE: 0x02 
D (310749) NimBLE: 0x00 
D (310749) NimBLE: 0x00 
D (310759) NimBLE: 

D (312769) NimBLE: looking up our sec; 
D (312769) NimBLE: peer_addr_type=0 peer_addr=
D (312769) NimBLE: 0x3f 
D (312769) NimBLE: 0x0e 
D (312769) NimBLE: 0x5b 
D (312769) NimBLE: 0xe3 
D (312769) NimBLE: 0xdb 
D (312779) NimBLE: 0xf4 
D (312779) NimBLE:  
D (312779) NimBLE: ediv=0x22c2 rand=0xbdd9f438e309ba39 
D (312789) NimBLE: 

D (312789) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18

D (312789) NimBLE: 0x1a 
D (312799) NimBLE: 0x20 
D (312799) NimBLE: 0x12 
D (312799) NimBLE: 0x00 
D (312809) NimBLE: 0x00 
D (312809) NimBLE: 0x7a 
D (312809) NimBLE: 0x4a 
D (312809) NimBLE: 0x22 
D (312819) NimBLE: 0x82 
D (312819) NimBLE: 0x52 
D (312819) NimBLE: 0x35 
D (312819) NimBLE: 0x27 
D (312829) NimBLE: 0x52 
D (312829) NimBLE: 0x5b 
D (312829) NimBLE: 0x40 
D (312829) NimBLE: 0x54 
D (312839) NimBLE: 0x40 
D (312839) NimBLE: 0xb2 
D (312839) NimBLE: 0x6f 
D (312839) NimBLE: 0xae 
D (312849) NimBLE: 0x7a 
D (312849) NimBLE: 

D (312849) BLE_SRV NIMBLE: bleprph_gap_event:585 encryption change event; status=7 
D (312859) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (312869) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (312869) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (312879) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (312879) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (312889) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (312889) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (312899) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (312899) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (312909) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=19 
D (312919) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (312929) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (312929) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (312939) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (312939) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (312949) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (312949) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (312959) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (312959) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (312969) BLE_SRV NIMBLE: bleprph_gap_event:542 

D (312999) APPLIANCE_GSC_SYSTEM_STATE: appliance_clear_system_state:48 Restored current system state to SYS_INTEGRATED(8)
D (313009) NimBLE: looking up peer sec; 
D (313009) NimBLE: 

D (313009) NimBLE: looking up peer sec; 
D (313019) NimBLE: 

I (313019) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 1 (max 9)

assert failed: ble_hs_hci_cmd_tx ble_hs_hci.c:315 (ble_hs_hci_ack == ((void *)0))

ok case:

I (259059) NimBLE: GAP procedure initiated: advertise; 
I (259069) NimBLE: disc_mode=2
D (259069) MQTT_CLIENT: Sent PING successful
I (259069) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
D (259079) MQTT_CLIENT: PING sent
I (259089) NimBLE: 

D (259089) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15

D (259099) NimBLE: 0x06 
D (259099) NimBLE: 0x20 
D (259099) NimBLE: 0x0f 
D (259109) NimBLE: 0x30 
D (259109) NimBLE: 0x00 
D (259109) NimBLE: 0x60 
D (259109) NimBLE: 0x00 
D (259119) NimBLE: 0x00 
D (259119) NimBLE: 0x00 
D (259119) NimBLE: 0x00 
D (259119) NimBLE: 0x00 
D (259129) NimBLE: 0x00 
D (259129) NimBLE: 0x00 
D (259129) NimBLE: 0x00 
D (259129) NimBLE: 0x00 
D (259139) NimBLE: 0x00 
D (259139) NimBLE: 0x07 
D (259139) NimBLE: 0x00 
D (259139) NimBLE: 

D (259149) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1

D (259149) NimBLE: 0x0a 
D (259159) NimBLE: 0x20 
D (259159) NimBLE: 0x01 
D (259159) NimBLE: 0x01 
D (259159) NimBLE: 

D (259329) TRANSPORT_WS: Opcode: 2, mask: 0, len: 2

D (259339) TRANSPORT_WS: Actual data to receive (2) are longer than ws buffer (1)
D (259339) TRANSPORT_BASE: remain data in cache, need to read again
D (259339) MQTT_CLIENT: mqtt_message_receive: first byte: 0xd0
D (259349) TRANSPORT_BASE: remain data in cache, need to read again
D (259359) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x0
D (259359) MQTT_CLIENT: mqtt_message_receive: total message length: 2 (already read: 2)
D (259369) MQTT_CLIENT: mqtt_message_receive: transport_read():2 2
D (259379) MQTT_CLIENT: msg_type=13, msg_id=0
D (259379) MQTT_CLIENT: MQTT_MSG_TYPE_PINGRESP
D (262979) NimBLE: 0x12 
D (262989) NimBLE: 0xf7 
D (262989) NimBLE: 0xfb 
D (262989) NimBLE: 0xa4 
D (262989) NimBLE: 0x71 
D (262989) NimBLE: 0x44 
D (262989) NimBLE: 

D (262989) BLE_SRV NIMBLE: bleprph_gap_event:513 connection established; status=0 
D (262999) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (263009) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (263009) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (263019) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (263019) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (263029) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (263029) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (263039) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (263039) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

D (263079) APPLIANCE_GSC_SYSTEM_STATE: appliance_set_system_state:38 Changed current system state to SYS_QUICKCONNECT(9)
I (263089) BLE_SRV NIMBLE: CON HANDLER 0 
D (263089) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2

D (263099) NimBLE: 0x16 
D (263099) NimBLE: 0x20 
D (263109) NimBLE: 0x02 
D (263109) NimBLE: 0x00 
D (263109) NimBLE: 0x00 
D (263109) NimBLE: 

D (263179) NimBLE: looking up our sec; 
D (263179) NimBLE: peer_addr_type=0 peer_addr=
D (263179) NimBLE: 0x3f 
D (263179) NimBLE: 0x0e 
D (263179) NimBLE: 0x5b 
D (263179) NimBLE: 0xe3 
D (263189) NimBLE: 0xdb 
D (263189) NimBLE: 0xf4 
D (263189) NimBLE:  
D (263189) NimBLE: ediv=0x22c2 rand=0xbdd9f438e309ba39 
D (263199) NimBLE: 

D (263199) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18

D (263209) NimBLE: 0x1a 
D (263209) NimBLE: 0x20 
D (263209) NimBLE: 0x12 
D (263219) NimBLE: 0x00 
D (263219) NimBLE: 0x00 
D (263219) NimBLE: 0x7a 
D (263219) NimBLE: 0x4a 
D (263229) NimBLE: 0x22 
D (263229) NimBLE: 0x82 
D (263229) NimBLE: 0x52 
D (263229) NimBLE: 0x35 
D (263239) NimBLE: 0x27 
D (263239) NimBLE: 0x52 
D (263239) NimBLE: 0x5b 
D (263239) NimBLE: 0x40 
D (263249) NimBLE: 0x54 
D (263249) NimBLE: 0x40 
D (263249) NimBLE: 0xb2 
D (263259) NimBLE: 0x6f 
D (263259) NimBLE: 0xae 
D (263259) NimBLE: 0x7a 
D (263259) NimBLE: 

D (263299) BLE_SRV NIMBLE: bleprph_gap_event:585 encryption change event; status=0 
D (263299) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (263299) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (263309) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (263309) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (263319) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (263319) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (263329) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (263329) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (263339) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=1 authenticated=1 bonded=1

D (263509) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (263509) NimBLE: 0x03 
D (263509) NimBLE: 0x00 
D (263509) NimBLE: 0x04 
D (263509) NimBLE: 0x00 
D (263519) NimBLE: 0x02 
D (263519) NimBLE: 0x0f 
D (263519) NimBLE: 0x02 
D (263519) NimBLE: 

D (263529) NimBLE: host tx hci data; handle=0 length=7

D (263529) NimBLE: ble_hs_hci_acl_tx(): 
D (263539) NimBLE: 0x00 
D (263539) NimBLE: 0x00 
D (263539) NimBLE: 0x07 
D (263539) NimBLE: 0x00 
D (263549) NimBLE: 0x03 
D (263549) NimBLE: 0x00 
D (263549) NimBLE: 0x04 
D (263549) NimBLE: 0x00 
D (263559) NimBLE: 0x03 
D (263559) NimBLE: 0x0f 
D (263559) NimBLE: 0x02 
D (263559) NimBLE: 

D (263569) BLE_SRV NIMBLE: bleprph_gap_event:617 mtu update event; conn_handle=0 cid=4 mtu=527

D (263599) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=
D (263599) NimBLE: 0x05 
D (263599) NimBLE: 0x00 
D (263599) NimBLE: 0x04 
D (263599) NimBLE: 0x00 
D (263609) NimBLE: 0x12 
D (263609) NimBLE: 0x09 
D (263609) NimBLE: 0x00 
D (263609) NimBLE: 0x02 
D (263619) NimBLE: 0x00 
D (263619) NimBLE: 

D (263619) BLE_SRV NIMBLE: bleprph_gap_event:597 subscribe event; conn_handle=0 attr_handle=8 reason=1 prev_notify=0 cur_notify=0 prev_indicate=0 cur_indicate=1

D (263639) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 28
D (263639) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 20
D (263649) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 23
D (263649) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 33
D (263659) nvs: nvs_open_from_partition nimble_bond 1
D (263659) nvs: nvs_get_str_or_blob cccd_sec_1
D (263669) nvs: nvs_close 118
D (263669) nvs: nvs_open_from_partition nimble_bond 1
D (263679) nvs: nvs_get_str_or_blob cccd_sec_2
D (263679) nvs: nvs_close 119
D (263679) nvs: nvs_open_from_partition nimble_bond 1
D (263689) nvs: nvs_get_str_or_blob cccd_sec_3
D (263689) nvs: nvs_close 120
D (263699) nvs: nvs_open_from_partition nimble_bond 1
D (263699) nvs: nvs_get_str_or_blob cccd_sec_4
D (263709) nvs: nvs_close 121
D (263709) nvs: nvs_open_from_partition nimble_bond 1
D (263709) nvs: nvs_get_str_or_blob cccd_sec_5
D (263719) nvs: nvs_close 122
D (263719) nvs: nvs_open_from_partition nimble_bond 1
D (263729) nvs: nvs_get_str_or_blob cccd_sec_6
D (263729) nvs: nvs_close 123
D (263729) nvs: nvs_open_from_partition nimble_bond 1
D (263739) nvs: nvs_get_str_or_blob cccd_sec_7
D (263739) nvs: nvs_close 124
D (263749) nvs: nvs_open_from_partition nimble_bond 1
D (263749) nvs: nvs_get_str_or_blob cccd_sec_8
D (263759) nvs: nvs_close 125
D (263759) NIMBLE_NVS: Persisting CCCD value in NVS...
D (263759) nvs: nvs_open_from_partition nimble_bond 1
D (263769) nvs: nvs_get_str_or_blob cccd_sec_1
D (263769) nvs: nvs_close 126
D (263779) NIMBLE_NVS: Empty NVS index found = 1 for obj_type = 3
D (263779) nvs: nvs_open_from_partition nimble_bond 1
D (263789) nvs: nvs_set_blob cccd_sec_1 16
D (263789) nvs: nvs_close 127
D (263799) NimBLE: host tx hci data; handle=0 length=5

D (263799) NimBLE: ble_hs_hci_acl_tx(): 
D (263799) NimBLE: 0x00 
D (263809) NimBLE: 0x00 
D (263809) NimBLE: 0x05 
D (263809) NimBLE: 0x00 
D (263809) NimBLE: 0x01 
D (263819) NimBLE: 0x00 
D (263819) NimBLE: 0x04 
D (263819) NimBLE: 0x00 
D (263829) NimBLE: 0x13 
D (263829) NimBLE: 

D (263829) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (263839) NimBLE: 0x35 
D (263839) NimBLE: 0x0c 
D (263839) NimBLE: 0x05 
D (263839) NimBLE: 0x01 
D (263849) NimBLE: 0x00 
D (263849) NimBLE: 0x00 
D (263849) NimBLE: 0x02 
D (263849) NimBLE: 0x00 
D (263859) NimBLE: 

D (264109) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (264109) NimBLE: 0x03 
D (264109) NimBLE: 0x00 
D (264109) NimBLE: 0x04 
D (264109) NimBLE: 0x00 
D (264119) NimBLE: 0x0a 
D (264119) NimBLE: 0x0c 
D (264119) NimBLE: 0x00 
D (264119) NimBLE: 

D (264129) BLE_SRV NIMBLE: gatt_svr_serve_chrs:300 Type: 0 , conn_handle : 0x0, attr_handle : 0xc
D (264129) BLE CHARACTERISTICS: ble_characteristic_device_type
D (264139) NimBLE: host tx hci data; handle=0 length=8

D (264149) NimBLE: ble_hs_hci_acl_tx(): 
D (264149) NimBLE: 0x00 
D (264149) NimBLE: 0x00 
D (264159) NimBLE: 0x08 
D (264159) NimBLE: 0x00 
D (264159) NimBLE: 0x04 
D (264159) NimBLE: 0x00 
D (264169) NimBLE: 0x04 
D (264169) NimBLE: 0x00 
D (264169) NimBLE: 0x0b 
D (264169) NimBLE: 0x31 
D (264179) NimBLE: 0x30 
D (264179) NimBLE: 0x37 
D (264179) NimBLE: 

D (264279) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (264279) NimBLE: 0x35 
D (264279) NimBLE: 0x0c 
D (264279) NimBLE: 0x05 
D (264289) NimBLE: 0x01 
D (264289) NimBLE: 0x00 
D (264289) NimBLE: 0x00 
D (264289) NimBLE: 0x01 
D (264299) NimBLE: 0x00 
D (264299) NimBLE: 

D (264439) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (264439) NimBLE: 0x03 
D (264439) NimBLE: 0x00 
D (264439) NimBLE: 0x04 
D (264439) NimBLE: 0x00 
D (264449) NimBLE: 0x0a 
D (264449) NimBLE: 0x25 
D (264449) NimBLE: 0x00 
D (264449) NimBLE: 

D (264459) NimBLE: host tx hci data; handle=0 length=8

D (264459) NimBLE: ble_hs_hci_acl_tx(): 
D (264469) NimBLE: 0x00 
D (264469) NimBLE: 0x00 
D (264469) NimBLE: 0x08 
D (264469) NimBLE: 0x00 
D (264479) NimBLE: 0x04 
D (264479) NimBLE: 0x00 
D (264479) NimBLE: 0x04 
D (264479) NimBLE: 0x00 
D (264489) NimBLE: 0x0b 
D (264489) NimBLE: 0x31 
D (264489) NimBLE: 0x30 
D (264489) NimBLE: 0x37 
D (264499) NimBLE: 

D (264599) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (264599) NimBLE: 0x35 
D (264599) NimBLE: 0x0c 
D (264599) NimBLE: 0x05 
D (264599) NimBLE: 0x01 
D (264599) NimBLE: 0x00 
D (264609) NimBLE: 0x00 
D (264609) NimBLE: 0x01 
D (264609) NimBLE: 0x00 
D (264619) NimBLE: 

D (264769) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (264769) NimBLE: 0x03 
D (264769) NimBLE: 0x00 
D (264769) NimBLE: 0x04 
D (264769) NimBLE: 0x00 
D (264779) NimBLE: 0x0a 
D (264779) NimBLE: 0x27 
D (264779) NimBLE: 0x00 
D (264779) NimBLE: 

D (264789) NimBLE: host tx hci data; handle=0 length=24

D (264789) NimBLE: ble_hs_hci_acl_tx(): 
D (264799) NimBLE: 0x00 
D (264799) NimBLE: 0x00 
D (264799) NimBLE: 0x18 
D (264799) NimBLE: 0x00 
D (264809) NimBLE: 0x14 
D (264809) NimBLE: 0x00 
D (264809) NimBLE: 0x04 
D (264809) NimBLE: 0x00 
D (264819) NimBLE: 0x0b 
D (264819) NimBLE: 0x30 
D (264819) NimBLE: 0x5a 
D (264819) NimBLE: 0x31 
D (264829) NimBLE: 0x30 
D (264829) NimBLE: 0x46 
D (264829) NimBLE: 0x46 
D (264829) NimBLE: 0x30 
D (264839) NimBLE: 0x31 
D (264839) NimBLE: 0x31 
D (264839) NimBLE: 0x33 
D (264839) NimBLE: 0x31 
D (264849) NimBLE: 0x44 
D (264849) NimBLE: 0x30 
D (264849) NimBLE: 0x30 
D (264859) NimBLE: 0x30 
D (264859) NimBLE: 0x41 
D (264859) NimBLE: 0x30 
D (264859) NimBLE: 0x30 
D (264869) NimBLE: 0x01 
D (264869) NimBLE: 

D (264969) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (264969) NimBLE: 0x35 
D (264969) NimBLE: 0x0c 
D (264969) NimBLE: 0x05 
D (264969) NimBLE: 0x01 
D (264979) NimBLE: 0x00 
D (264979) NimBLE: 0x00 
D (264979) NimBLE: 0x01 
D (264979) NimBLE: 0x00 
D (264989) NimBLE: 

D (265129) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (265129) NimBLE: 0x03 
D (265129) NimBLE: 0x00 
D (265129) NimBLE: 0x04 
D (265129) NimBLE: 0x00 
D (265139) NimBLE: 0x0a 
D (265139) NimBLE: 0x2b 
D (265139) NimBLE: 0x00 
D (265139) NimBLE: 

D (265149) NimBLE: host tx hci data; handle=0 length=52

D (265149) NimBLE: ble_hs_hci_acl_tx(): 
D (265159) NimBLE: 0x00 
D (265159) NimBLE: 0x00 
D (265159) NimBLE: 0x34 
D (265159) NimBLE: 0x00 
D (265169) NimBLE: 0x30 
D (265169) NimBLE: 0x00 
D (265169) NimBLE: 0x04 
D (265169) NimBLE: 0x00 
D (265179) NimBLE: 0x0b 
D (265179) NimBLE: 0x30 
D (265179) NimBLE: 0x31 
D (265179) NimBLE: 0x2e 
D (265189) NimBLE: 0x30 
D (265189) NimBLE: 0x31 
D (265189) NimBLE: 0x2e 
D (265189) NimBLE: 0x35 
D (265199) NimBLE: 0x39 
D (265199) NimBLE: 0x31 
D (265199) NimBLE: 0x38 
D (265199) NimBLE: 0x37 
D (265209) NimBLE: 0x39 
D (265209) NimBLE: 0x2f 
D (265209) NimBLE: 0x30 
D (265219) NimBLE: 0x31 
D (265219) NimBLE: 0x2e 
D (265219) NimBLE: 0x30 
D (265219) NimBLE: 0x31 
D (265229) NimBLE: 0x2e 
D (265229) NimBLE: 0x35 
D (265229) NimBLE: 0x39 
D (265229) NimBLE: 0x31 
D (265239) NimBLE: 0x38 
D (265239) NimBLE: 0x37 
D (265239) NimBLE: 0x39 
D (265239) NimBLE: 0x2f 
D (265249) NimBLE: 0x30 
D (265249) NimBLE: 0x31 
D (265249) NimBLE: 0x2e 
D (265249) NimBLE: 0x30 
D (265259) NimBLE: 0x31 
D (265259) NimBLE: 0x2e 
D (265259) NimBLE: 0x35 
D (265259) NimBLE: 0x39 
D (265269) NimBLE: 0x31 
D (265269) NimBLE: 0x38 
D (265269) NimBLE: 0x37 
D (265269) NimBLE: 0x39 
D (265279) NimBLE: 0x2f 
D (265279) NimBLE: 0x30 
D (265279) NimBLE: 0x31 
D (265289) NimBLE: 0x2e 
D (265289) NimBLE: 0x35 
D (265289) NimBLE: 0x30 
D (265289) NimBLE: 0x2e 
D (265299) NimBLE: 0x30 
D (265299) NimBLE: 0x30 
D (265299) NimBLE: 

D (265399) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (265399) NimBLE: 0x35 
D (265399) NimBLE: 0x0c 
D (265399) NimBLE: 0x05 
D (265409) NimBLE: 0x01 
D (265409) NimBLE: 0x00 
D (265409) NimBLE: 0x00 
D (265409) NimBLE: 0x01 
D (265419) NimBLE: 0x00 
D (265419) NimBLE: 

D (265549) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (265549) NimBLE: 0x03 
D (265549) NimBLE: 0x00 
D (265549) NimBLE: 0x04 
D (265549) NimBLE: 0x00 
D (265559) NimBLE: 0x0a 
D (265559) NimBLE: 0x29 
D (265559) NimBLE: 0x00 
D (265559) NimBLE: 

D (265569) NimBLE: host tx hci data; handle=0 length=20

D (265569) NimBLE: ble_hs_hci_acl_tx(): 
D (265579) NimBLE: 0x00 
D (265579) NimBLE: 0x00 
D (265579) NimBLE: 0x14 
D (265579) NimBLE: 0x00 
D (265589) NimBLE: 0x10 
D (265589) NimBLE: 0x00 
D (265589) NimBLE: 0x04 
D (265589) NimBLE: 0x00 
D (265599) NimBLE: 0x0b 
D (265599) NimBLE: 0x30 
D (265599) NimBLE: 0x30 
D (265599) NimBLE: 0x31 
D (265609) NimBLE: 0x2f 
D (265609) NimBLE: 0x30 
D (265609) NimBLE: 0x30 
D (265609) NimBLE: 0x33 
D (265619) NimBLE: 0x2f 
D (265619) NimBLE: 0x30 
D (265619) NimBLE: 0x30 
D (265619) NimBLE: 0x32 
D (265629) NimBLE: 0x2f 
D (265629) NimBLE: 0x30 
D (265629) NimBLE: 0x30 
D (265639) NimBLE: 0x31 
D (265639) NimBLE: 

D (265739) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (265739) NimBLE: 0x35 
D (265739) NimBLE: 0x0c 
D (265739) NimBLE: 0x05 
D (265739) NimBLE: 0x01 
D (265749) NimBLE: 0x00 
D (265749) NimBLE: 0x00 
D (265749) NimBLE: 0x01 
D (265749) NimBLE: 0x00 
D (265759) NimBLE: 

D (265909) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=
D (265909) NimBLE: 0x03 
D (265909) NimBLE: 0x00 
D (265909) NimBLE: 0x04 
D (265909) NimBLE: 0x00 
D (265919) NimBLE: 0x0a 
D (265919) NimBLE: 0x2d 
D (265919) NimBLE: 0x00 
D (265919) NimBLE: 

D (265929) NimBLE: host tx hci data; handle=0 length=24

D (265929) NimBLE: ble_hs_hci_acl_tx(): 
D (265939) NimBLE: 0x00 
D (265939) NimBLE: 0x00 
D (265939) NimBLE: 0x18 
D (265939) NimBLE: 0x00 
D (265949) NimBLE: 0x14 
D (265949) NimBLE: 0x00 
D (265949) NimBLE: 0x04 
D (265949) NimBLE: 0x00 
D (265959) NimBLE: 0x0b 
D (265959) NimBLE: 0x30 
D (265959) NimBLE: 0x31 
D (265959) NimBLE: 0x2e 
D (265969) NimBLE: 0x37 
D (265969) NimBLE: 0x30 
D (265969) NimBLE: 0x2e 
D (265969) NimBLE: 0x5a 
D (265979) NimBLE: 0x31 
D (265979) NimBLE: 0x30 
D (265979) NimBLE: 0x2e 
D (265979) NimBLE: 0x30 
D (265989) NimBLE: 0x33 
D (265989) NimBLE: 0x30 
D (265989) NimBLE: 0x30 
D (265999) NimBLE: 0x2e 
D (265999) NimBLE: 0x36 
D (265999) NimBLE: 0x42 
D (265999) NimBLE: 0x30 
D (266009) NimBLE: 0x30 
D (266009) NimBLE: 

D (266109) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (266109) NimBLE: 0x35 
D (266109) NimBLE: 0x0c 
D (266109) NimBLE: 0x05 
D (266109) NimBLE: 0x01 
D (266119) NimBLE: 0x00 
D (266119) NimBLE: 0x00 
D (266119) NimBLE: 0x01 
D (266119) NimBLE: 0x00 
D (266129) NimBLE: 

D (267709) NimBLE: ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=
D (267709) NimBLE: 0x07 
D (267709) NimBLE: 0x00 
D (267709) NimBLE: 0x04 
D (267709) NimBLE: 0x00 
D (267719) NimBLE: 0x08 
D (267719) NimBLE: 0x01 
D (267719) NimBLE: 0x00 
D (267719) NimBLE: 0x05 
D (267729) NimBLE: 0x00 
D (267729) NimBLE: 0x00 
D (267729) NimBLE: 0x2a 
D (267729) NimBLE: 

D (267739) NimBLE: host tx hci data; handle=0 length=27

D (267739) NimBLE: ble_hs_hci_acl_tx(): 
D (267749) NimBLE: 0x00 
D (267749) NimBLE: 0x00 
D (267749) NimBLE: 0x1b 
D (267749) NimBLE: 0x00 
D (267759) NimBLE: 0x17 
D (267759) NimBLE: 0x00 
D (267759) NimBLE: 0x04 
D (267759) NimBLE: 0x00 
D (267769) NimBLE: 0x09 
D (267769) NimBLE: 0x15 
D (267769) NimBLE: 0x03 
D (267769) NimBLE: 0x00 
D (267779) NimBLE: 0x47 
D (267779) NimBLE: 0x52 
D (267779) NimBLE: 0x4f 
D (267779) NimBLE: 0x48 
D (267789) NimBLE: 0x45 
D (267789) NimBLE: 0x5f 
D (267789) NimBLE: 0x42 
D (267799) NimBLE: 0x52 
D (267799) NimBLE: 0x31 
D (267799) NimBLE: 0x5f 
D (267799) NimBLE: 0x30 
D (267809) NimBLE: 0x30 
D (267809) NimBLE: 0x31 
D (267809) NimBLE: 0x31 
D (267809) NimBLE: 0x33 
D (267819) NimBLE: 0x31 
D (267819) NimBLE: 0x44 
D (267819) NimBLE: 0x30 
D (267819) NimBLE: 0x30 
D (267829) NimBLE: 

D (267929) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0035 len=5

D (267929) NimBLE: 0x35 
D (267929) NimBLE: 0x0c 
D (267929) NimBLE: 0x05 
D (267929) NimBLE: 0x01 
D (267939) NimBLE: 0x00 
D (267939) NimBLE: 0x00 
D (267939) NimBLE: 0x01 
D (267939) NimBLE: 0x00 
D (267949) NimBLE: 

D (271069) BLE_SRV NIMBLE: bleprph_gap_event:597 subscribe event; conn_handle=0 attr_handle=8 reason=2 prev_notify=0 cur_notify=0 prev_indicate=1 cur_indicate=0

D (271069) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 28
D (271079) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 20
D (271079) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 23
D (271089) BLE_SRV NIMBLE: bleprph_gap_event:602 8 vs 33
D (271089) BLE_SRV NIMBLE: bleprph_gap_event:540 disconnect; reason=531 
D (271099) BLE_SRV NIMBLE: handle=0 our_ota_addr_type=0 our_ota_addr=
D (271109) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (271109) BLE_SRV NIMBLE:  our_id_addr_type=0 our_id_addr=
D (271119) BLE_SRV NIMBLE: 84:0d:8e:e6:78:da
D (271119) BLE_SRV NIMBLE:  peer_ota_addr_type=0 peer_ota_addr=
D (271129) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (271129) BLE_SRV NIMBLE:  peer_id_addr_type=0 peer_id_addr=
D (271139) BLE_SRV NIMBLE: f4:db:e3:5b:0e:3f
D (271139) BLE_SRV NIMBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=1 authenticated=1 bonded=1

D (271149) BLE_SRV NIMBLE: bleprph_gap_event:542 

D (271179) APPLIANCE_GSC_SYSTEM_STATE: appliance_clear_system_state:48 Restored current system state to SYS_INTEGRATED(8)
D (271189) NimBLE: looking up peer sec; 
D (271189) NimBLE: 

D (271199) NimBLE: looking up peer sec; 
D (271199) NimBLE: 

I (271199) BLE_SRV NIMBLE: bleprph_remove_old_bondings:455 ble: number of stored bondings: 1 (max 9)
D (271209) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0008 len=32

D (271219) NimBLE: 0x08 
D (271219) NimBLE: 0x20 
D (271219) NimBLE: 0x20 
D (271229) NimBLE: 0x1a 
D (271229) NimBLE: 0x02 
D (271229) NimBLE: 0x01 
D (271229) NimBLE: 0x06 
D (271239) NimBLE: 0x11 
D (271239) NimBLE: 0x07 
D (271239) NimBLE: 0xf1 
D (271239) NimBLE: 0xb0 
D (271249) NimBLE: 0xdb 
D (271249) NimBLE: 0xe8 
D (271249) NimBLE: 0x39 
D (271249) NimBLE: 0x24 
D (271259) NimBLE: 0xd0 
D (271259) NimBLE: 0xb7 
D (271259) NimBLE: 0xe2 
D (271259) NimBLE: 0x43 
D (271269) NimBLE: 0x82 
D (271269) NimBLE: 0x97 
D (271269) NimBLE: 0xba 
D (271269) NimBLE: 0x1b 
D (271279) NimBLE: 0xf3 
D (271279) NimBLE: 0x33 
D (271279) NimBLE: 0x04 
D (271289) NimBLE: 0xff 
D (271289) NimBLE: 0xe5 
D (271289) NimBLE: 0x02 
D (271289) NimBLE: 0x00 
D (271299) NimBLE: 0x00 
D (271299) NimBLE: 0x03 
D (271299) NimBLE: 0x00 
D (271299) NimBLE: 0x00 
D (271309) NimBLE: 0x00 
D (271309) NimBLE: 

D (271309) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0009 len=32

D (271319) NimBLE: 0x09 
D (271319) NimBLE: 0x20 
D (271319) NimBLE: 0x20 
D (271329) NimBLE: 0x15 
D (271329) NimBLE: 0x14 
D (271329) NimBLE: 0x09 
D (271329) NimBLE: 0x47 
D (271339) NimBLE: 0x52 
D (271339) NimBLE: 0x4f 
D (271339) NimBLE: 0x48 
D (271339) NimBLE: 0x45 
D (271349) NimBLE: 0x5f 
D (271349) NimBLE: 0x42 
D (271349) NimBLE: 0x52 
D (271349) NimBLE: 0x31 
D (271359) NimBLE: 0x5f 
D (271359) NimBLE: 0x30 
D (271359) NimBLE: 0x30 
D (271359) NimBLE: 0x31 
D (271369) NimBLE: 0x31 
D (271369) NimBLE: 0x33 
D (271369) NimBLE: 0x31 
D (271369) NimBLE: 0x44 
D (271379) NimBLE: 0x30 
D (271379) NimBLE: 0x30 
D (271379) NimBLE: 0x04 
D (271389) NimBLE: 0xff 
D (271389) NimBLE: 0xe5 
D (271389) NimBLE: 0x02 
D (271389) NimBLE: 0x00 
D (271399) NimBLE: 0x00 
D (271399) NimBLE: 0x03 
D (271399) NimBLE: 0x00 
D (271399) NimBLE: 0x00 
D (271409) NimBLE: 0x00 
D (271409) NimBLE: 

I have found this issue that look similar, but it's still open https://esp32.com/viewtopic.php?t=26819

rahult-github commented 2 years ago

Hi @mgagic ,

I re-analyzed the first crash log .. What i observe is:

  1. A disconnect event is getting posted ( disconnection may be due to any reason )
  2. I see set adv fields command. Am assuming, the application code on disconnect attempts to do advertising ( this is my assumption based on logs )
  3. Host tries to send a command, but a crash is observed, since it tries to check if pointer is NULL or not. When the crash occurs, ble_hs_hci_ack is coming as NULL in this log, pointing to the fact that it is not pointing to valid value when the last rx_ack happened.

I tried to simulate this case using the exisitng bleprph and blecent examples of idf. But in overnight run, i did observe a connection failure, but i am not seeing any crash. So far. it would be useful if you can provide some pseudo code of the application, i can integrate the same in existing applications and try to reproduce the scenario to debug.

Thanks, Rahul

mgagic commented 2 years ago

Hi @rahult-github, thanks for your support it's really appreciated!

Sorry for the delay, but it seems we've figured out the problem. When the disconnect event happens we had an internal error reporting to the main controller via uart which was done before doing the advertising. It looks like this messed up the timing/flow of the internal nimBLE process which resulted in the crash. Moving this outside of the disconnect handling seems to have solved the issue. We've been testing for a few days now, and no crashes occurred.