Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC (CON-908) #749

Open
GeeklinkSmart opened this issue Nov 22, 2023 · 9 comments
Open

Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC (CON-908) #749

GeeklinkSmart opened this issue Nov 22, 2023 · 9 comments

Comments

@GeeklinkSmart
Copy link

GeeklinkSmart commented Nov 22, 2023 •
edited
Loading

I am developing a bridge product using ESP MATTER SDK, but after the program runs, it will prompt this error, which makes it impossible to use chiptool to debug the product. Here are the related logs.

My idf version :V5.1.1
Device :ESP32S3

logs：
I (1066) wifi:wifi driver task: 3fcf7a64, prio:23, stack:6656, core=0
I (1075) wifi:wifi firmware version: dc6ffb6
I (1075) wifi:wifi certification version: v7.0
I (1079) wifi:config NVS flash: enabled
I (1083) wifi:config nano formating: disabled
I (1087) wifi:Init data frame dynamic rx buffer num: 32
I (1092) wifi:Init static rx mgmt buffer num: 5
I (1096) wifi:Init management short buffer num: 32
I (1100) wifi:Init static tx buffer num: 16
I (1104) wifi:Init tx cache buffer num: 32
I (1108) wifi:Init static tx FG buffer num: 2
I (1112) wifi:Init static rx buffer size: 1600
I (1116) wifi:Init static rx buffer num: 10
I (1119) wifi:Init dynamic rx buffer num: 32
I (00:00:00.301) wifi_init: rx ba win: 6
I (00:00:00.305) wifi_init: tcpip mbox: 32
I (00:00:00.310) wifi_init: udp mbox: 6
I (00:00:00.314) wifi_init: tcp mbox: 6
I (00:00:00.319) wifi_init: tcp tx win: 5744
I (00:00:00.323) wifi_init: tcp rx win: 5744
I (00:00:00.328) wifi_init: tcp mss: 1460
I (00:00:00.333) wifi_init: WiFi/LWIP prefer SPIRAM
I (00:00:00.338) wifi_init: WiFi IRAM OP enabled
I (00:00:00.344) wifi_init: WiFi RX IRAM OP enabled
I (1184) chip[DL]: NVS set: chip-counters/reboot-count = 63 (0x3F)
I (1187) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (00:00:00.001) BLE_INIT: BT controller compile version [59725b5]
I (00:00:00.008) BLE_INIT: Bluetooth MAC: 48:27:e2:08:d4:f2

I (00:00:00.014) phy_init: phy_version 620,ec7ec30,Sep 5 2023,13:49:13
I (1256) chip[DL]: I (1257) chip[BLE]: Starting ESP WiFi layerGATT Event: 0 (if 3)

I (1258) wifi:mode : sta (48:27:e2:08:d4:f0)
I (1259) wifi:enable tsf
W (1261) wifi:Haven't to connect to a suitable AP now!
I (1266) chip[DL]: Done driving station state, nothing else to do...
W (1273) wifi:Haven't to connect to a suitable AP now!
I (1278) chip[DL]: Done driving station state, nothing else to do...
I (1285) chip[SVR]: Initializing subscription resumption storage...
I (1292) chip[SVR]: Server initializing...
I (1297) chip[TS]: Last Known Good Time: 2023-11-21T15:15:01
I (1303) chip[DMG]: AccessControl: initializing
I (1307) chip[DMG]: Examples::AccessControlDelegate::Init
I (1313) chip[DMG]: AccessControl: setting
I (1318) chip[DMG]: DefaultAclStorage: initializing
I (1323) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1340) chip[ZCL]: Using ZAP configuration...
I (00:00:00.153) esp_matter_cluster: Cluster plugin init common callback
I (1342) chip[DMG]: AccessControlCluster: initializing
I (1347) chip[ZCL]: 0x3c1358a4ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1356) chip[ZCL]: Initiating Admin Commissioning cluster.
E (1362) chip[ZCL]: Duplicate attribute override registration failed
I (1370) chip[DIS]: Updating services using commissioning mode 1
I (1376) chip[DIS]: CHIP minimal mDNS started advertising.
I (1382) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (1392) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 78B5D97F0DE8DDC0.
I (1403) chip[DIS]: mDNS service published: _matterc._udp
I (1409) chip[IN]: CASE Server enabling CASE session setups
I (1415) chip[SVR]: Joining Multicast groups
I (1420) chip[SVR]: Server Listening...
I (00:00:00.237) esp_matter_core: Dynamic endpoint 0 added
I (00:00:00.243) esp_matter_core: Dynamic endpoint 1 added
I (1437) chip[DL]: WIFI_EVENT_STA_START
W (1441) wifi:Haven't to connect to a suitable AP now!
I (1446) chip[DL]: Done driving station state, nothing else to do...
I (00:00:00.265) app_main: Commissioning window opened
I (1460) chip[BLE]: GATT Event: 22 (if 3)
I (1463) chip[BLE]: GAP Event: 22
I (1467) chip[BLE]: GATT Event: 12 (if 3)
I (1471) chip[DL]: CHIPoBLE GATT service started
I (1477) chip[BLE]:
I (1481) chip[BLE]: GAP Event: 4
I (1483) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name )
E (1492) BT_BTM: No random address yet, please set random address and try

E (1500) BT_APPL: bta_dm_ble_set_adv_params_all(), fail to set ble adv params.
I (1508) chip[BLE]: GAP Event: 6
E (1511) chip[DL]: ESP_GAP_BLE_ADV_START_COMPLETE_EVT error: 1
E (1518) chip[DL]: Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC
I (1526) chip[BLE]: GAP Event: 6
E (1530) chip[DL]: ESP_GAP_BLE_ADV_START_COMPLETE_EVT error: 13
E (1536) chip[DL]: Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC
W (00:00:00.358) esp_matter_core: Server Cluster 0x0000001D on endpoint 0x0002 already exists. Not creating again.
W (00:00:00.368) esp_matter_core: Attribute 0x00000000 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.379) esp_matter_core: Attribute 0x00000001 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.389) esp_matter_core: Attribute 0x00000002 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.400) esp_matter_core: Attribute 0x00000003 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.411) esp_matter_core: Attribute 0x0000FFFC on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.422) esp_matter_core: Attribute 0x0000FFFD on cluster 0x0000001D already exists. Not creating again.
I (00:00:00.435) esp_matter_bridge: Cluster plugin init for the new added endpoint
E (1628) chip[ZCL]: Duplicate attribute override registration failed
I (00:00:00.448) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
@github-actions github-actions bot changed the title Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC (CON-908) Nov 22, 2023
@dhrishi
Copy link
Collaborator

dhrishi commented Nov 22, 2023

@GeeklinkSmart Can you recreate this issue using any of the existing examples in esp-matter? If not, please share a patch that we can apply to test this out. Also, it will be helpful if you can attach (not paste) the entire logs since bootup

@jonsmirl
Copy link
Contributor 

I (1483) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name )
E (1492) BT_BTM: No random address yet, please set random address and try

Missing the address?

@GeeklinkSmart
Copy link
Author

@GeeklinkSmart Can you recreate this issue using any of the existing examples in esp-matter? If not, please share a patch that we can apply to test this out. Also, it will be helpful if you can attach (not paste) the entire logs since bootup

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x2b (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3818,len:0x1544
load:0x403c9700,len:0x4
load:0x403c9704,len:0xd5c
load:0x403cc700,len:0x2edc
entry 0x403c991c
I (27) boot: ESP-IDF v5.1.1-577-g6b1f40b9bf-dirty 2nd stage bootloader
I (27) boot: compile time Nov 21 2023 16:21:15
I (28) boot: Multicore bootloader
I (32) boot: chip revision: v0.1
I (36) qio_mode: Enabling default flash chip QIO
I (41) boot.esp32s3: Boot SPI Speed : 80MHz
I (46) boot.esp32s3: SPI Mode : QIO
I (50) boot.esp32s3: SPI Flash Size : 16MB
I (55) boot: Enabling RNG early entropy source...
I (61) boot: Partition Table:
I (64) boot: ## Label Usage Type ST Offset Length
I (72) boot: 0 home WiFi data 01 02 00009000 00004000
I (79) boot: 1 esp_secure_cert unknown 3f 06 0000d000 00002000
I (86) boot: 2 otadata OTA data 01 00 0000f000 00002000
I (94) boot: 3 phy_init RF data 01 01 00011000 00001000
I (101) boot: 4 coredump Unknown data 01 03 00012000 00008000
I (109) boot: 5 log_info Unknown data 01 fe 0001a000 00006000
I (117) boot: 6 ota_0 OTA app 00 10 00020000 00500000
I (124) boot: 7 ota_1 OTA app 00 11 00520000 00500000
I (132) boot: 8 nvs WiFi data 01 02 00a20000 00040000
I (139) boot: 9 font Unknown data 01 06 00a60000 005a0000
I (147) boot: End of partition table
I (151) esp_image: segment 0: paddr=00020020 vaddr=3c130020 size=7d05ch (512092) map
I (237) esp_image: segment 1: paddr=0009d084 vaddr=3fc97700 size=02f94h ( 12180) load
I (240) esp_image: segment 2: paddr=000a0020 vaddr=42000020 size=127ba8h (1211304) map
I (426) esp_image: segment 3: paddr=001c7bd0 vaddr=3fc9a694 size=01af4h ( 6900) load
I (428) esp_image: segment 4: paddr=001c96cc vaddr=40374000 size=136c4h ( 79556) load
I (456) boot: Loaded app from partition at offset 0x20000
I (456) boot: Disabling RNG early entropy source...
I (468) cpu_start: Multicore app
I (468) esp_psram: Found 2MB PSRAM device
I (468) esp_psram: Speed: 80MHz
I (469) cpu_start: Pro cpu up.
I (472) cpu_start: Starting app cpu, entry point is 0x40374f28
0x40374f28: call_start_cpu1 at /home/gluser/esp/esp-idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (709) esp_psram: SPI SRAM memory test OK
I (718) cpu_start: Pro cpu start user code
I (718) cpu_start: cpu freq: 240000000 Hz
I (718) cpu_start: Application information:
I (721) cpu_start: Project name: knob_2m_bridge_1_5
I (727) cpu_start: App version: 8.2
I (731) cpu_start: Compile time: Nov 21 2023 16:21:03
I (737) cpu_start: ELF file SHA256: ef5bb1a967750f52...
I (743) cpu_start: ESP-IDF: v5.1.1-577-g6b1f40b9bf-dirty
I (750) cpu_start: Min chip rev: v0.0
I (755) cpu_start: Max chip rev: v0.99
I (760) cpu_start: Chip rev: v0.1
I (764) heap_init: Initializing. RAM available for dynamic allocation:
I (771) heap_init: At 3FCA89E0 len 00040D30 (259 KiB): D/IRAM
I (778) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DIRAM
I (785) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (791) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (797) esp_psram: Adding pool of 2037K of PSRAM memory to heap allocator
I (805) spi_flash: detected chip: gd
I (809) spi_flash: flash io: qio
W (813) ADC: legacy driver is deprecated, please migrate to esp_adc/adc_oneshot.h
I (822) sleep: Configure to isolate all GPIO pins in sleep state
I (828) sleep: Enable automatic switching of GPIO sleep configuration
I (835) coexist: coex firmware version: 8770c12
I (840) coexist: coexist rom version e7ae62f
I (845) app_start: Starting scheduler on CPU0
I (0) app_start: Starting scheduler on CPU1
I (00:00:00.132) main_task: Started on CPU0
I (00:00:00.142) main_task: Calling app_main()
I (00:00:00.229) app_main: 1 largest_free size :262144,total:292936
E (00:00:00.230) app_main: Matter START INIT ............
I (00:00:00.238) pp: pp rom version: e7ae62f
I (00:00:00.238) net80211: net80211 rom version: e7ae62f
I (1066) wifi:wifi driver task: 3fcf7a64, prio:23, stack:6656, core=0
I (1075) wifi:wifi firmware version: dc6ffb6
I (1075) wifi:wifi certification version: v7.0
I (1079) wifi:config NVS flash: enabled
I (1083) wifi:config nano formating: disabled
I (1087) wifi:Init data frame dynamic rx buffer num: 32
I (1092) wifi:Init static rx mgmt buffer num: 5
I (1096) wifi:Init management short buffer num: 32
I (1100) wifi:Init static tx buffer num: 16
I (1104) wifi:Init tx cache buffer num: 32
I (1108) wifi:Init static tx FG buffer num: 2
I (1112) wifi:Init static rx buffer size: 1600
I (1116) wifi:Init static rx buffer num: 10
I (1119) wifi:Init dynamic rx buffer num: 32
I (00:00:00.301) wifi_init: rx ba win: 6
I (00:00:00.305) wifi_init: tcpip mbox: 32
I (00:00:00.310) wifi_init: udp mbox: 6
I (00:00:00.314) wifi_init: tcp mbox: 6
I (00:00:00.319) wifi_init: tcp tx win: 5744
I (00:00:00.323) wifi_init: tcp rx win: 5744
I (00:00:00.328) wifi_init: tcp mss: 1460
I (00:00:00.333) wifi_init: WiFi/LWIP prefer SPIRAM
I (00:00:00.338) wifi_init: WiFi IRAM OP enabled
I (00:00:00.344) wifi_init: WiFi RX IRAM OP enabled
I (1184) chip[DL]: NVS set: chip-counters/reboot-count = 64 (0x40)
I (1187) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (00:00:00.001) BLE_INIT: BT controller compile version [59725b5]
I (00:00:00.008) BLE_INIT: Bluetooth MAC: 48:27:e2:08:d4:f2

I (00:00:00.014) phy_init: phy_version 620,ec7ec30,Sep 5 2023,13:49:13
I (1261) chip[DL]: I (1261) chip[BLE]: Starting ESP WiFi layerGATT Event: 0 (if 3)

I (1263) wifi:mode : sta (48:27:e2:08:d4:f0)
I (1263) wifi:enable tsf
W (1266) wifi:Haven't to connect to a suitable AP now!
I (1271) chip[DL]: Done driving station state, nothing else to do...
W (1278) wifi:Haven't to connect to a suitable AP now!
I (1282) chip[DL]: Done driving station state, nothing else to do...
I (1289) chip[SVR]: Initializing subscription resumption storage...
I (1297) chip[SVR]: Server initializing...
I (1301) chip[TS]: Last Known Good Time: 2023-11-21T15:15:01
I (1307) chip[DMG]: AccessControl: initializing
I (1312) chip[DMG]: Examples::AccessControlDelegate::Init
I (1318) chip[DMG]: AccessControl: setting
I (1323) chip[DMG]: DefaultAclStorage: initializing
I (1328) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1345) chip[ZCL]: Using ZAP configuration...
I (00:00:00.158) esp_matter_cluster: Cluster plugin init common callback
I (1346) chip[DMG]: AccessControlCluster: initializing
I (1352) chip[ZCL]: 0x3c1358a4ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1360) chip[ZCL]: Initiating Admin Commissioning cluster.
E (1366) chip[ZCL]: Duplicate attribute override registration failed
I (1375) chip[DIS]: Updating services using commissioning mode 1
I (1380) chip[DIS]: CHIP minimal mDNS started advertising.
I (1386) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (1397) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 943ADEF615647EE5.
I (1407) chip[DIS]: mDNS service published: _matterc._udp
I (1413) chip[IN]: CASE Server enabling CASE session setups
I (1420) chip[SVR]: Joining Multicast groups
I (1424) chip[SVR]: Server Listening...
I (00:00:00.242) esp_matter_core: Dynamic endpoint 0 added
I (00:00:00.248) esp_matter_core: Dynamic endpoint 1 added
I (1442) chip[DL]: WIFI_EVENT_STA_START
W (1445) wifi:Haven't to connect to a suitable AP now!
I (1450) chip[DL]: Done driving station state, nothing else to do...
I (00:00:00.270) app_main: Commissioning window opened
I (1465) chip[BLE]: GATT Event: 22 (if 3)
I (1467) chip[BLE]: GAP Event: 22
I (1472) chip[BLE]: GATT Event: 12 (if 3)
I (1476) chip[DL]: CHIPoBLE GATT service started
I (1481) chip[BLE]:
I (1485) chip[BLE]: GAP Event: 4
I (1488) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name )
E (1497) BT_BTM: No random address yet, please set random address and try

E (1504) BT_APPL: bta_dm_ble_set_adv_params_all(), fail to set ble adv params.
I (1512) chip[BLE]: GAP Event: 6
E (1516) chip[DL]: ESP_GAP_BLE_ADV_START_COMPLETE_EVT error: 1
E (1522) chip[DL]: Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC
I (1531) chip[BLE]: GAP Event: 6
E (1534) chip[DL]: ESP_GAP_BLE_ADV_START_COMPLETE_EVT error: 13
E (1541) chip[DL]: Disabling CHIPoBLE service due to error: Error CHIP:0x000000AC
W (00:00:00.363) esp_matter_core: Server Cluster 0x0000001D on endpoint 0x0002 already exists. Not creating again.
W (00:00:00.373) esp_matter_core: Attribute 0x00000000 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.383) esp_matter_core: Attribute 0x00000001 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.394) esp_matter_core: Attribute 0x00000002 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.405) esp_matter_core: Attribute 0x00000003 on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.416) esp_matter_core: Attribute 0x0000FFFC on cluster 0x0000001D already exists. Not creating again.
W (00:00:00.426) esp_matter_core: Attribute 0x0000FFFD on cluster 0x0000001D already exists. Not creating again.
I (00:00:00.439) esp_matter_bridge: Cluster plugin init for the new added endpoint
E (1633) chip[ZCL]: Duplicate attribute override registration failed
I (00:00:00.453) esp_matter_attribute: ********** W : Endpoint 0x0002's Cluster 0x00000003's Attribute 0x00000001 is 0 **********

Here is the entire logs since bootup .I test the belmesh_bridge in esp-matter/examples and it works ok ,but after I used it in my project , the problem occured

@GeeklinkSmart
Copy link
Author 

I (1483) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name )
E (1492) BT_BTM: No random address yet, please set random address and try

Missing the address?

Yeah, I don't know why,in my project i haven't set any address or call any function about ble init.
Here is my main function

extern "C" void app_main()
{
esp_err_t err = ESP_OK;

gpio_set_direction(11,GPIO_MODE_OUTPUT);
gpio_set_level(11,0);
/* Initialize the ESP NVS layer */
nvs_flash_init();

// Check_IO_Statue();

#ifdef MATTER_ENABLE

node::config_t node_config;
node_t *node = node::create(&node_config, app_attribute_update_cb, NULL);

/* These node and endpoint handles can be used to create/add other endpoints and clusters. */
if (!node) {
    ESP_LOGE(TAG, "Matter node creation failed");
}

aggregator::config_t aggregator_config;

endpoint_t *aggregator = endpoint::aggregator::create(node, &aggregator_config, ENDPOINT_FLAG_NONE, NULL);

if (!aggregator) {
    ESP_LOGE(TAG, "Matter aggregator endpoint creation failed");
}

aggregator_endpoint_id = endpoint::get_id(aggregator);

/* Matter start */
err = esp_matter::start(app_event_cb);
if (err != ESP_OK) {
    ESP_LOGE(TAG, "Matter start failed: %d", err);
}


err = app_bridge_initialize(node);
if (err != ESP_OK) {
    ESP_LOGE(TAG, "Failed to resume the bridged endpoints: %d", err);
}


#if CONFIG_ENABLE_CHIP_SHELL
	esp_matter::console::diagnostics_register_commands();
	esp_matter::console::init();
#endif

#endif

}

@GeeklinkSmart
Copy link
Author

main and log.txt

@GeeklinkSmart
Copy link
Author

After i choose nimble instead of bluedroid in menuconfig ,It works ok now

@dhrishi
Copy link
Collaborator

dhrishi commented Nov 28, 2023

@GeeklinkSmart Ok. Is there a specific reason you want to use Bluedroid instead of NimBLE host?

@GeeklinkSmart
Copy link
Author

@dhrishi I use it to connece with computer or other device to do something about playing music such as volume control ,next ,stop/play etc. when i choose NimBLE, I can't do this.

@shripad621git
Copy link
Contributor

shripad621git commented Jul 29, 2024 •
edited
Loading

@GeeklinkSmart , the error appears in the case of Bluedroid due to a missing function to set the random address.Can you please test out the changes specified in this comment here for Bluedroid.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@jonsmirl @dhrishi @GeeklinkSmart @shripad621git