exception while calling this->setup_connection() in mesh_connection.cpp

echavet commented 7 months ago

Hello,

nice work. I was curious to test your component, but obviously I ran into an error that causes the ship to boot.

Thread 
7 "loopTask" received signal SIGTRAP, Trace/breakpoint trap.
esphome::esp32_ble_client::BLECharacteristic::write_value (this=0x0, new_val=0x3fccd5d8 "\f\347\025\341\341\333\362\374\222\360\064\205f", new_val_size=17, write_type=ESP_GATT_WRITE_TYPE_NO_RSP) at src/esphome/components/esp32_ble_client/ble_characteristic.cpp:82
82    auto *client = this->service->client;

the call stack is

esp32_ble_tracker.cpp at line 400: client->gattc_event_handler(event, gattc_if, param);
ble.cpp at line 344: gattc_handler->gattc_event_handler(event, gattc_if, param);
ble.cpp at line 294: this->real_gattc_event_handler_(ble_event->event_.gattc.gattc_event, ble_event->event_.gattc.gattc_if, &ble_event->event_.gattc.gattc_param);
mesh_connection.cpp line 148: this->setup_connection();

esphome logs

``` [17:32:20][I][awox.connection:179]: Response OK, let's go [17:32:20][D][awox.connection:251]: combine mesh name + password: 6DDJn9u0:****** [17:32:20][I][awox.connection:184]: [0] [A4:C1:38:78:34:95] session key 11001011110000....00110100 [17:32:20][D][awox.connection:551]: [0] [A4:C1:38:78:34:95] request status update [17:32:20][D][awox.connection:541]: [0] [A4:C1:38:78:34:95] [65535] write_command packet DA => 00010000 [17:32:20][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_WRITE_CHAR_EVT [17:32:20][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_NOTIFY_EVT [17:32:20][D][awox.connection:355]: online status report: mesh: 13461, on: 0, color_mode: 0, sequence_mode: 0, candle_mode: 0, w_b: 127, temp: 25, c_b: 100, rgb: FFFFFF, mode: 8 00001000 [17:32:20][I][awox.mesh:338]: Added mesh_id: 13461, Number of found mesh devices = 1 [17:32:20][D][awox.mesh:474]: Call connection for 13461 [17:32:20][I][awox.mesh:485]: No active connection for 13461, we trigger message on all could be also a group [17:32:20][I][awox.connection:458]: 13461: OFF temp: 25 (127 %) ONLINE [17:32:20][W][awox.mesh.mqtt:135]: [13461] Can not yet send publish state for device [17:32:20][D][awox.mesh:407]: Delayed publish online/offline for 13461 - online [17:32:20][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_WRITE_CHAR_EVT [17:32:21][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_NOTIFY_EVT [17:32:21][D][awox.connection:379]: status report: mesh: 13461, on: 0, color_mode: 0, sequence_mode: 0, candle_mode: 0, w_b: 127, temp: 25, c_b: 100, rgb: FFFFFF, mode: 8 00001000 [17:32:21][I][awox.connection:458]: 13461: OFF temp: 25 (127 %) ONLINE [17:32:21][W][awox.mesh.mqtt:135]: [13461] Can not yet send publish state for device [17:32:21][W][component:214]: Component esp32_ble took a long time for an operation (0.67 s). [17:32:21][W][component:215]: Components should block for at most 20-30ms. [17:32:21][D][awox.connection:541]: [0] [A4:C1:38:78:34:95] [13461] write_command packet EA => 0001000000000000 [17:32:21][I][awox.connection:115]: still 1 queued commands [17:32:21][I][mqtt:234]: Connecting to MQTT... [17:32:21][D][esp-idf:000]: I (233117) MQTT_CLIENT: Client asked to disconnect [17:32:21][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_WRITE_CHAR_EVT [17:32:21][I][awox.connection:121]: 1 queued commands (debounce timer: -53, next command DD, for dest: 13461) [17:32:21][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_NOTIFY_EVT [17:32:21][D][awox.connection:395]: MAC report, dev [13461]: productID: 0x13 mac: A4:C1:38:78:34:95 [17:32:21][D][awox.mesh.mqtt:321]: [13461]: Sending discovery productID: 0x13 (SmartLIGHT Color Mesh 9 - SMLm_C9) mac: A4:C1:38:78:34:95 [17:32:21][I][awox.mesh.mqtt:117]: Publish online/offline for 13461 - online [17:32:21][W][component:214]: Component esp32_ble took a long time for an operation (0.09 s). [17:32:21][W][component:215]: Components should block for at most 20-30ms. [17:32:21][D][awox.connection:541]: [0] [A4:C1:38:78:34:95] [13461] write_command packet DD => 0000101000000001 [17:32:21][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_WRITE_CHAR_EVT [17:32:21][D][esp32_ble_client:110]: [0] [A4:C1:38:78:34:95] ESP_GATTC_NOTIFY_EVT [17:32:21][D][awox.connection:411]: Group report, dev [13461] 6 [17:32:21][I][awox.mesh:372]: Added group_id: 6, Number of found mesh groups = 1 [17:32:21][D][awox.connection:411]: Group report, dev [13461] 5 [17:32:21][I][awox.mesh:372]: Added group_id: 5, Number of found mesh groups = 2 [17:32:21][W][component:214]: Component esp32_ble took a long time for an operation (0.11 s). [17:32:21][W][component:215]: Components should block for at most 20-30ms. [17:32:21][I][awox.mesh.mqtt:129]: Publish online/offline for group 6 - online [17:32:21][I][awox.mesh.mqtt:129]: Publish online/offline for group 5 - online [17:32:21][W][component:214]: Component awox_mesh took a long time for an operation (0.06 s). [17:32:21][W][component:215]: Components should block for at most 20-30ms. [17:32:23][I][awox.mesh.mqtt:082]: Publish connection info, 1 connections, 1 device online [17:32:25][I][mqtt:274]: MQTT Connected! [17:32:25][W][component:214]: Component mqtt took a long time for an operation (0.18 s). [17:32:25][W][component:215]: Components should block for at most 20-30ms. [17:32:26][W][component:214]: Component mqtt took a long time for an operation (0.06 s). [17:32:26][W][component:215]: Components should block for at most 20-30ms. [17:32:26][W][component:214]: Component mqtt took a long time for an operation (0.09 s). [17:32:26][W][component:215]: Components should block for at most 20-30ms. [17:32:33][D][awox.mesh:088]: Found Awox device - A4:C1:38:5C:A2:C3. RSSI: -40 dB (total devices: 2) [17:32:40][D][awox.mesh:221]: Set mesh_id 13461 for device A4:C1:38:78:34:95 [17:32:40][D][awox.mesh:227]: Total devices: 2 [17:32:40][D][awox.mesh:230]: Available device A4:C1:38:5C:A2:C3 [0] => rssi: -40 [17:32:40][D][awox.mesh:230]: Available device A4:C1:38:78:34:95 [13461] => rssi: -9999 [17:32:40][D][awox.mesh:255]: Currently 1 mesh devices reachable through active connections (1 currently known and 1 fully recognized) [17:32:40][D][awox.mesh:261]: Try to connecty to device A4:C1:38:5C:A2:C3 no mesh id known yet [17:32:40][I][awox.mesh:139]: Try to connect A4:C1:38:5C:A2:C3 => rssi: -40 [17:32:40][I][awox.connection:117]: IDLE [17:32:40][D][esp32_ble_client:110]: [1] [A4:C1:38:5C:A2:C3] Found device [17:32:40][D][esp32_ble_tracker:661]: Found device A4:C1:38:5C:A2:C3 RSSI=-40 [17:32:40][D][esp32_ble_tracker:682]: Address Type: PUBLIC [17:32:40][I][awox.connection:125]: DISCOVERED [17:32:40][W][component:214]: Component awox_mesh took a long time for an operation (0.44 s). [17:32:40][W][component:215]: Components should block for at most 20-30ms. [17:32:40][D][esp32_ble_tracker:215]: Pausing scan to make connection... [17:32:40][D][awox.mesh:088]: Found Awox device - A4:C1:38:BD:F0:27. RSSI: -61 dB (total devices: 3) [17:32:40][D][awox.mesh:088]: Found Awox device - A4:C1:38:B3:13:D2. RSSI: -55 dB (total devices: 4) [17:32:40][I][awox.connection:129]: READY_TO_CONNECT [17:32:40][W][component:214]: Component esp32_ble_tracker took a long time for an operation (0.07 s). [17:32:40][W][component:215]: Components should block for at most 20-30ms. [17:32:40][I][esp32_ble_client:067]: [1] [A4:C1:38:5C:A2:C3] 0x00 Attempting BLE connection [17:32:40][I][awox.connection:133]: CONNECTING [17:32:40][W][component:214]: Component awox_mesh took a long time for an operation (0.12 s). [17:32:41][W][component:215]: Components should block for at most 20-30ms. [17:32:54][D][esp32_ble_client:110]: [1] [A4:C1:38:5C:A2:C3] ESP_GATTC_CONNECT_EVT [17:32:54][D][esp32_ble_client:110]: [1] [A4:C1:38:5C:A2:C3] ESP_GATTC_OPEN_EVT [17:32:54][I][awox.connection:137]: CONNECTED [17:32:54][W][component:214]: Component esp32_ble took a long time for an operation (0.13 s). [17:32:54][W][component:215]: Components should block for at most 20-30ms. [17:32:54][D][esp32_ble_tracker:266]: Starting scan... [17:32:54][D][awox.mesh:117]: scan end [17:32:54][W][component:214]: Component esp32_ble_tracker took a long time for an operation (0.11 s). [17:32:54][W][component:215]: Components should block for at most 20-30ms. [17:32:58][D][esp32_ble_client:306]: [1] [A4:C1:38:5C:A2:C3] Event 46 [17:32:58][D][esp32_ble_client:110]: [1] [A4:C1:38:5C:A2:C3] ESP_GATTC_SEARCH_CMPL_EVT [17:32:58][I][esp32_ble_client:227]: [1] [A4:C1:38:5C:A2:C3] Connected [17:32:58][I][awox.connection:147]: Connected.... [17:32:58][D][awox.connection:251]: combine mesh name + password: 6DDJn9u0:******* WARNING awox-mesh @ 192.168.8.246: Connection error occurred: Ping response not received after 90.0 seconds INFO Processing unexpected disconnect from ESPHome API for awox-mesh @ 192.168.8.246 ```

yaml conf

``` substitutions: name: "awox-mesh" friendly_name: AwoX Mesh bluetooth relay esphome: name: ${name} friendly_name: ${friendly_name} platformio_options: board_build.flash_mode: dio esp32: board: esp32-s3-devkitc-1 framework: type: esp-idf variant: esp32s3 flash_size: 8MB mqtt: broker: home-io.local username: awox_mesh2mqtt password: !secret mqtt_awox_password discovery: true debug: update_interval: 5s # Enable logging logger: level: DEBUG # Enable Home Assistant API api: services: - service: reboot then: - logger.log: "Redémarrage en cours..." - lambda: |- esp_restart(); encryption: key: !secret encryption_key ota: password: !secret ota_pwd wifi: #ssid: !secret wifi_ssid #password: !secret wifi_password networks: - ssid : !secret wifi_ssid password: !secret wifi_password - ssid: !secret wifi_ssid2 password: !secret wifi_password2 #- ssid: !secret wifi_ssid2 # password: !secret wifi_password2 # Enable fallback hotspot (captive portal) in case wifi connection fails ap: ssid: "awox-mesh-proxy Hotspot" password: !secret ota_pwd # pas assez de place pour update ota #web_server: # port: 80 time: - platform: homeassistant id: homeassistant_time # this setting is for local component (code is not on github) external_components: # - source: # type: git # url: https://github.com/fsaris/EspHome-AwoX-BLE-mesh-hub # ref: main - source: type: local path: components esp32_ble_tracker: scan_parameters: active: false awox_mesh: mesh_name: !secret mesh_name mesh_password: !secret mesh_password device_info: - product_id: 0x13 device_type: RGB name: SmartLIGHT Color Mesh 9 model: SMLm_C9 manufacturer: AwoX - product_id: 0x25 device_type: RGB name: EGLOPanel 30X30 model: EPanel_300 manufacturer: EGLO # Text sensors with general information. text_sensor: # Expose ESPHome version as sensor. - platform: version name: ${name} ESPHome Version # Expose WiFi information as sensors. - platform: wifi_info ip_address: name: ${name} IP ssid: name: ${name} SSID bssid: name: ${name} BSSID - platform: debug device: name: "Device Info" reset_reason: name: "Reset Reason" # Sensors with general information. sensor: # - platform: debug # free: # name: "Heap Free" # # Uptime sensor. # - platform: uptime # name: ${name} Uptime # WiFi Signal sensor. - platform: wifi_signal name: ${name} WiFi Signal update_interval: 60s ```

compilation traces

``` awox-mesh % esphome compile AwoX-Mesh.yaml INFO ESPHome 2024.2.2 INFO Reading configuration AwoX-Mesh.yaml... INFO Detected timezone 'Europe/Paris' INFO Generating C++ source... INFO Compiling app... Processing awox-mesh (board: esp32-s3-devkitc-1; framework: espidf; platform: platformio/espressif32@5.4.0) ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Tool Manager: Installing espressif/toolchain-xtensa-esp32s3 @ 8.4.0+2021r2-patch5 INFO Installing espressif/toolchain-xtensa-esp32s3 @ 8.4.0+2021r2-patch5 Unpacking [####################################] 100% Tool Manager: toolchain-xtensa-esp32s3@8.4.0+2021r2-patch5 has been installed! INFO toolchain-xtensa-esp32s3@8.4.0+2021r2-patch5 has been installed! Tool Manager: Installing espressif/toolchain-esp32ulp @ 2.35.0-20220830 INFO Installing espressif/toolchain-esp32ulp @ 2.35.0-20220830 Unpacking [####################################] 100% Tool Manager: toolchain-esp32ulp@2.35.0-20220830 has been installed! INFO toolchain-esp32ulp@2.35.0-20220830 has been installed! HARDWARE: ESP32S3 240MHz, 320KB RAM, 8MB Flash - framework-espidf @ 3.40406.240122 (4.4.6) - tool-cmake @ 3.16.4 - tool-ninja @ 1.9.0 - toolchain-esp32ulp @ 2.35.0-20220830 - toolchain-riscv32-esp @ 8.4.0+2021r2-patch5 - toolchain-xtensa-esp32s3 @ 8.4.0+2021r2-patch5 Reading CMake configuration... Generating assembly for certificate bundle... Dependency Graph |-- noise-c @ 0.1.4 |-- ArduinoJson @ 6.18.5 ... Flash: [==== ] 41.4% (used 1629589 bytes from 3932160 bytes) Building .pioenvs/awox-mesh/firmware.bin Creating esp32s3 image... Successfully created esp32s3 image. esp32_create_combined_bin([".pioenvs/awox-mesh/firmware.bin"], [".pioenvs/awox-mesh/firmware.elf"]) Wrote 0x19df00 bytes to file /Users/echavet/Documents/2024/awox-mesh/.esphome/build/awox-mesh/.pioenvs/awox-mesh/firmware-factory.bin, ready to flash to offset 0x0 ======================================================================== [SUCCESS] Took 42.82 seconds ======================================================================== ```

fsaris commented 7 months ago

Hi, not sure if the call stack is related to the issue you run into.

I would expect some nullpointer exception or memory issue.

It looks that the MQTT isn't stable. It tries to (re-) connect at some point but it should already have a connection.

Can you provide a log from start-up until restart?

What version of esphome are you using and what version of this component?

echavet commented 7 months ago

thank you for your response. the versions are all in my message.

ESPHome 2024.2.2 
framework-espidf @ 3.40406.240122 (4.4.6)

The chip does receive a SIGTRAP signal which might be caused by another thread but here are some more logs:

[10:56:06][I][awox.connection:137]: CONNECTED
[10:56:06][D][esp32_ble_tracker:266]: Starting scan...
[10:56:06][D][awox.mesh:115]: scan end
[10:56:06][D][awox.mesh:226]: Total devices: 2
[10:56:06][D][awox.mesh:229]: Available device A4:C1:38:5C:A2:C3 [0] => rssi: -59
[10:56:06][D][awox.mesh:229]: Available device A4:C1:38:BD:F0:27 [0] => rssi: -9999
[10:56:06][D][awox.mesh:254]: Currently 0 mesh devices reachable through active connections (0 currently known and 0 fully recognized)
[10:56:06][D][awox.mesh:128]: No devices found to connect to
[10:56:08][D][esp32_ble_client:306]: [0] [A4:C1:38:5C:A2:C3] Event 46
[10:56:08][D][esp32_ble_client:110]: [0] [A4:C1:38:5C:A2:C3] ESP_GATTC_SEARCH_CMPL_EVT
[10:56:08][I][esp32_ble_client:227]: [0] [A4:C1:38:5C:A2:C3] Connected
[10:56:08][I][awox.connection:147]: Connected....
[10:56:08][D][awox.connection:251]: combine mesh name + password: 6DDJn9u0:032dfbd3
[10:56:08]Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
[10:56:08]
[10:56:08]Core  1 register dump:
[10:56:08]PC      : 0x42016abd  PS      : 0x00060430  A0      : 0x82016b22  A1      : 0x3fceddc0  
WARNING Decoded 0x42016abd: esphome::esp32_ble_client::BLECharacteristic::write_value(unsigned char*, short, esp_gatt_write_type_t) at /Users/echavet/Documents/2024/awox-mesh/.esphome/build/awox-mesh/src/esphome/components/esp32_ble_client/ble_characteristic.cpp:82
[10:56:08]A2      : 0x00000000  A3      : 0x3fcc7aa4  A4      : 0x00000011  A5      : 0x00000001  
[10:56:08]A6      : 0x00000000  A7      : 0x3fcede71  A8      : 0x00000011  A9      : 0x3fceddd0  
[10:56:08]A10     : 0x3fcede88  A11     : 0x3fcede58  A12     : 0x00000000  A13     : 0x00000000  
[10:56:08]A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000018  EXCCAUSE: 0x0000001c  
[10:56:08]EXCVADDR: 0x00000024  LBEG    : 0x40056fc5  LEND    : 0x40056fe7  LCOUNT  : 0xffffffff  
[10:56:08]
[10:56:08]
[10:56:08]Backtrace: 0x42016aba:0x3fceddc0 0x42016b1f:0x3fcede10 0x42014718:0x3fcede30 0x42014ec7:0x3fcedf50 0x4211cfaa:0x3fcedfc0 0x42017669:0x3fcedfe0 0x4211cf55:0x3fcee000 0x420163cd:0x3fcee020 0x4211d679:0x3fcee040 0x4211d765:0x3fcee060 0x42022669:0x3fcee080 0x42024b0a:0x3fcee0b0 0x420158be:0x3fcee0d0

I think you'll agree that this points to a null pointer or memory address violation. The issue seems to originate from the BLECharacteristic::write_value() method. I'm considering a few possibilities for the cause of this issue:

A BLE device in my home might be processed as an Awox device but does not match the expected data, leading to a null pointer.
There could be a mismatch in the ESP-IDF version.
I'm currently out of other ideas.
The first hypothesis is supported by the logs, which show the USB chip connecting to the device A4:C1:38:5C:A2:C3, a BLE thermometer from Xiaomi, and not an Awox sensor.

I guess I could prevent the error from ocuring with a filter on mac with only awox devices in the "mac_addresses_allowed" field. I'll try.

fsaris commented 7 months ago

@echavet tnx for your investigation. I added some nullptr checks to assure the BLE characters are found before trying to "use" them

fsaris commented 7 months ago

this is resolved with latest dev version

fsaris / EspHome-AwoX-BLE-mesh-hub

exception while calling this->setup_connection() in mesh_connection.cpp #82