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

CHIP Error 0x00000032 when trying to send cluster commands #33442

Open
mulligan252 opened this issue May 14, 2024 · 4 comments
Open

CHIP Error 0x00000032 when trying to send cluster commands #33442

mulligan252 opened this issue May 14, 2024 · 4 comments
Labels
bug Something isn't working linux needs triage

Comments

@mulligan252
Copy link

mulligan252 commented May 14, 2024 •
edited

Reproduction steps

I have an ESP32-C6-DevKitM-1. I have flashed this with the Matter light example from the esp-matter SDK. I am using Ubuntu 22.04 as a Virtual machine on Windows for doing the cross compilation and running chip-tool etc.

I then commission my device as follows : chip-tool pairing ble-wifi 0x7283 'My Network' 123456789 20202021 3840

This all works fine. My device connects to my local network and and I can ping its IP address etc.

I don't know, why but I am unable then to turn on or off the LED on the board, or even send any cluster command using the chip tool for example :

chip-tool onoff toggle 0x7283 0x01

I get the following logs below :

[1715694336.819940][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1715694336.821260][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1715694336.821301][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1715694336.822772][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1715694336.822880][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1715694336.822947][4472:4472] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1715694336.823209][4472:4472] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-WSN4ht)
[1715694336.823563][4472:4472] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1715694336.823929][4472:4472] CHIP:DL: NVS set: chip-counters/reboot-count = 17 (0x11)
[1715694336.824140][4472:4472] CHIP:DL: Got Ethernet interface: enp0s3
[1715694336.824322][4472:4472] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1715694336.824621][4472:4472] CHIP:DL: Failed to get WiFi interface
[1715694336.824671][4472:4472] CHIP:DL: Failed to reset WiFi statistic counts
[1715694336.824715][4472:4472] CHIP:IN: UDP::Init bind&listen port=0
[1715694336.824781][4472:4472] CHIP:IN: UDP::Init bound to port=46740
[1715694336.824798][4472:4472] CHIP:IN: BLEBase::Init - setting/overriding transport
[1715694336.824813][4472:4472] CHIP:IN: TransportMgr initialized
[1715694336.824873][4472:4472] CHIP:FP: Initializing FabricTable from persistent storage
[1715694336.824918][4472:4472] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1715694336.825519][4472:4472] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x35CFE666CE838CD1, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1715694336.826572][4472:4472] CHIP:ZCL: Using ZAP configuration...
[1715694336.827095][4472:4472] CHIP:CTL: System State Initialized...
[1715694336.827193][4472:4472] CHIP:CTL: Setting attestation nonce to random value
[1715694336.827270][4472:4472] CHIP:CTL: Setting CSR nonce to random value
[1715694336.827431][4472:4474] CHIP:DL: CHIP task running
[1715694336.827562][4472:4474] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1715694336.827676][4472:4474] CHIP:CTL: Setting attestation nonce to random value
[1715694336.827716][4472:4474] CHIP:CTL: Setting CSR nonce to random value
[1715694336.827934][4472:4474] CHIP:CTL: Generating NOC
[1715694336.828143][4472:4474] CHIP:FP: Validating NOC chain
[1715694336.828544][4472:4474] CHIP:FP: NOC chain validation successful
[1715694336.828586][4472:4474] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1715694336.828602][4472:4474] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1715694336.828617][4472:4474] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1715694336.828631][4472:4474] CHIP:TS: Retaining current Last Known Good Time
[1715694336.829780][4472:4474] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1715694336.835566][4472:4474] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1715694336.845253][4472:4474] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 35CFE666CE838CD1)
[1715694336.859605][4472:4474] CHIP:TOO: Sending command to node 0x7283
[1715694336.860118][4472:4474] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283]
[1715694336.860377][4472:4474] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1715694336.860615][4472:4474] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2
[1715694337.063755][4472:4474] CHIP:DIS: Checking node lookup status after 203 ms
[1715694356.834065][4472:4472] CHIP:CTL: Shutting down the commissioner
[1715694356.834211][4472:4472] CHIP:CTL: Shutting down the controller
[1715694356.834268][4472:4472] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Cancelling incomplete address resolution as device is being deleted.
[1715694356.834350][4472:4472] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1715694356.834384][4472:4472] CHIP:FP: Forgetting fabric 0x1
[1715694356.834424][4472:4472] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1715694356.834519][4472:4472] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1715694356.835051][4472:4472] CHIP:TS: Reverted Last Known Good Time to previous value
[1715694356.835101][4472:4472] CHIP:CTL: Shutting down the commissioner
[1715694356.835134][4472:4472] CHIP:CTL: Shutting down the controller
[1715694356.835167][4472:4472] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1715694356.835263][4472:4472] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1715694356.835397][4472:4472] CHIP:FP: Shutting down FabricTable
[1715694356.835434][4472:4472] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1715694356.835502][4472:4472] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1715694356.835605][4472:4472] CHIP:TS: Reverted Last Known Good Time to previous value
[1715694356.836108][4472:4472] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-sI6X0o)
[1715694356.836685][4472:4472] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1715694356.837441][4472:4472] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1715694356.837514][4472:4472] CHIP:DL: Inet Layer shutdown
[1715694356.837539][4472:4472] CHIP:DL: BLE shutdown
[1715694356.837595][4472:4472] CHIP:DL: System Layer shutdown
[1715694356.837755][4472:4472] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:617: CHIP Error 0x00000032: Timeout

Bug prevalence

always

GitHub hash of the SDK that was being used

5bb5c9e

Platform

esp32

Platform Version(s)

No response

Type

Platform Issue

Anything else?

No response
@mulligan252 mulligan252 added bug Something isn't working needs triage labels May 14, 2024
@github-actions github-actions bot added the linux label May 14, 2024
@bzbarsky-apple
Copy link
Contributor

Well, chip-tool can't discover your device over DNS-SD. Is the device advertising? Is the chip-tool on the same wi-fi network as the device? @mulligan252

@bzbarsky-apple
Copy link
Contributor

That said, if commissioning succeeded, presumably chip-tool could find the advertisement at that point....

Does it help to pass a longer --timeout value for the toggle attempt?

@mulligan252
Copy link
Author

mulligan252 commented May 14, 2024 •
edited

Well, chip-tool can't discover your device over DNS-SD. Is the device advertising? Is the chip-tool on the same wi-fi network as the device? @mulligan252

@bzbarsky-apple Thanks for your reply. The chip-tool is on the same wi-fi network as the device. Commissioning appears to be successful. Below are the logs when the device boots up every time. There are some wi-fi connection issues initially, but seems to resolve itself eventually. This this look normal? I can ping the device on the network via its IP address from any computer then.

rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x1804
load:0x4086c410,len:0xe58
load:0x4086e610,len:0x2e20
entry 0x4086c41a
I (23) boot: ESP-IDF v5.2.1 2nd stage bootloader
I (24) boot: compile time May 10 2024 11:16:46
I (24) boot: chip revision: v0.0
I (26) boot.esp32c6: SPI Speed      : 80MHz
I (31) boot.esp32c6: SPI Mode       : DIO
I (36) boot.esp32c6: SPI Flash Size : 4MB
I (41) boot: Enabling RNG early entropy source...
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (64) boot:  1 nvs              WiFi data        01 02 00010000 0000c000
I (72) boot:  2 nvs_keys         NVS keys         01 04 0001c000 00001000
I (79) boot:  3 otadata          OTA data         01 00 0001d000 00002000
I (87) boot:  4 phy_init         RF data          01 01 0001f000 00001000
I (94) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (102) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (109) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (117) boot: End of partition table
I (121) esp_image: segment 0: paddr=00020020 vaddr=42140020 size=42288h (270984) map
I (186) esp_image: segment 1: paddr=000622b0 vaddr=40800000 size=0dd68h ( 56680) load
I (200) esp_image: segment 2: paddr=00070020 vaddr=42000020 size=13e9f8h (1305080) map
I (469) esp_image: segment 3: paddr=001aea20 vaddr=4080dd68 size=0e264h ( 57956) load
I (484) esp_image: segment 4: paddr=001bcc8c vaddr=4081bfd0 size=03ec8h ( 16072) load
I (488) esp_image: segment 5: paddr=001c0b5c vaddr=50000000 size=00004h (     4) load
I (496) boot: Loaded app from partition at offset 0x20000
I (497) boot: Disabling RNG early entropy source...
I (512) cpu_start: Unicore app
W (521) clk: esp_perip_clk_init() has not been implemented yet
I (528) cpu_start: Pro cpu start user code
I (528) cpu_start: cpu freq: 160000000 Hz
I (528) cpu_start: Application information:
I (531) cpu_start: Project name:     light
I (536) cpu_start: App version:      1.0
I (540) cpu_start: Compile time:     May 10 2024 11:16:34
I (546) cpu_start: ELF file SHA256:  ba163e08d...
I (552) cpu_start: ESP-IDF:          v5.2.1
I (557) cpu_start: Min chip rev:     v0.0
I (561) cpu_start: Max chip rev:     v0.99
I (566) cpu_start: Chip rev:         v0.0
I (571) heap_init: Initializing. RAM available for dynamic allocation:
I (578) heap_init: At 40832140 len 0004A4D0 (297 KiB): RAM
I (584) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (590) heap_init: At 50000004 len 00003FE4 (15 KiB): RTCRAM
I (597) spi_flash: detected chip: generic
I (601) spi_flash: flash io: dio
W (606) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`
I (617) sleep: Configure to isolate all GPIO pins in sleep state
I (623) sleep: Enable automatic switching of GPIO sleep configuration
I (630) coexist: coex firmware version: 77cd7f8
I (635) coexist: coexist rom version 5b8dcfa
I (640) main_task: Started on CPU0
I (640) main_task: Calling app_main()
I (660) led_indicator: LED Indicator Version: 0.9.2
I (660) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (660) led_indicator: Indicator create successfully. type:LED Strips mode, hardware_data:0x408367e0, blink_lists:custom
I (670) button: IoT Button Version: 3.2.0
I (680) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (690) app_main: Light created with endpoint_id 1
I (690) pp: pp rom version: 5b8dcfa
I (700) net80211: net80211 rom version: 5b8dcfa
I (710) wifi:wifi driver task: 4083fd48, prio:23, stack:6656, core=0
I (710) wifi:wifi firmware version: a9f5b59
I (710) wifi:wifi certification version: v7.0
I (710) wifi:config NVS flash: enabled
I (720) wifi:config nano formating: disabled
I (720) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N
I (730) wifi:Init data frame dynamic rx buffer num: 32
I (730) wifi:Init static rx mgmt buffer num: 5
I (740) wifi:Init management short buffer num: 32
I (740) wifi:Init dynamic tx buffer num: 32
I (740) wifi:Init static tx FG buffer num: 2
I (750) wifi:Init static rx buffer size: 1700
I (750) wifi:Init static rx buffer num: 10
I (760) wifi:Init dynamic rx buffer num: 32
I (760) wifi_init: rx ba win: 6
I (760) wifi_init: tcpip mbox: 32
I (770) wifi_init: udp mbox: 6
I (770) wifi_init: tcp mbox: 6
I (780) wifi_init: tcp tx win: 5760
I (780) wifi_init: tcp rx win: 5760
I (780) wifi_init: tcp mss: 1440
I (790) wifi_init: WiFi IRAM OP enabled
I (790) wifi_init: WiFi RX IRAM OP enabled
I (820) chip[DL]: NVS set: chip-counters/reboot-count = 38 (0x26)
I (820) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (820) BLE_INIT: Using main XTAL as clock source
I (830) BLE_INIT: ble controller commit:[217f1bf]
I (830) phy_init: phy_version 250,e14681b,Jan 24 2024,17:43:11
I (880) phy: libbtbb version: 939f79c, Jan 24 2024, 17:43:26
I (880) NimBLE: GAP procedure initiated: stop advertising.

I (880) NimBLE: Failed to restore IRKs from store; status=8

I (880) CHIP[DL]: BLE host-controller synced
I (1390) chip[DL]: Starting ESP WiFi layer
W (1390) wifi:(bf)761:0x600a7cac:0x01b4b4b0
W (1390) wifi:(agc)0x600a7128:0xd2184800, min.avgNF:0xce->0xd2(dB), RCalCount:0x184, min.RRssi:0x800(-128.00)
W (1390) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (1400) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (1400) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (1400) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (1410) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (1410) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (1410) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (1420) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (1420) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (1420) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (1430) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (1430) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (1430) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (1440) wifi:mode : sta (54:32:04:07:17:7c)
I (1440) wifi:enable tsf
W (1450) wifi:Haven't to connect to a suitable AP now!
I (1450) chip[DL]: Attempting to connect WiFi station interface
I (1460) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (1470) chip[DL]: Done driving station state, nothing else to do...
I (1470) chip[SVR]: Initializing subscription resumption storage...
I (1480) chip[SVR]: Server initializing...
I (1480) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (1490) chip[DMG]: AccessControl: initializing
I (1500) chip[DMG]: Examples::AccessControlDelegate::Init
I (1500) chip[DMG]: AccessControl: setting
I (1510) chip[DMG]: DefaultAclStorage: initializing
I (1510) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1470) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1520) wifi:(connect)dot11_authmode:0x3, pairwise_cipher:0x3, group_cipher:0x3
I (1530) wifi:state: init -> auth (b0)
I (1530) chip[ZCL]: Using ZAP configuration...
I (1540) esp_matter_cluster: Cluster plugin init common callback
I (1550) chip[DMG]: AccessControlCluster: initializing
I (1550) chip[ZCL]: 0x42146420 ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1560) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1540) wifi:state: auth -> init (8a0)
I (1570) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1580) chip[DIS]: Updating services using commissioning mode 1
I (1580) chip[DIS]: CHIP minimal mDNS started advertising.
I (1590) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (1600) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D6AE8150D313F113.
I (1610) chip[DIS]: mDNS service published: _matterc._udp
I (1620) chip[IN]: CASE Server enabling CASE session setups
I (1620) chip[SVR]: Joining Multicast groups
I (1630) chip[SVR]: Server Listening...
I (1630) esp_matter_core: Dynamic endpoint 0 added
I (1640) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (1650) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (1660) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (1670) chip[ZCL]: 0x42146420 ep 1 clus 0x0000_0062 attr 0x0000_0000 not supported
I (1680) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (1690) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is null **********
I (1710) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (1720) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (1730) chip[ZCL]: Endpoint 1 On/off already set to new value
I (1740) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000002 is 1 **********
I (1750) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000003 is 254 **********
I (1760) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x0000FFFC is 3 **********
I (1770) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
I (1780) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00004000 is 64 **********
I (1790) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
I (1810) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004010 is null **********
I (1820) esp_matter_core: Dynamic endpoint 1 added
I (1830) chip[DL]: WIFI_EVENT_STA_START
W (1830) wifi:Haven't to connect to a suitable AP now!
I (1830) chip[DL]: Attempting to connect WiFi station interface
I (1840) chip[DL]: Done driving station state, nothing else to do...
W (1850) wifi:Haven't to connect to a suitable AP now!
E (1850) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (1860) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1870) NimBLE: GAP procedure initiated: advertise;
I (1880) NimBLE: disc_mode=2
I (1880) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1890) NimBLE:

I (1890) chip[DL]: CHIPoBLE advertising started
I (1900) app_main: Commissioning window opened
I (1900) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
I (1910) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (1920) wifi:Haven't to connect to a suitable AP now!
I (1920) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected
I (1930) chip[DL]: Next WiFi station reconnect in 100 ms
I (1940) chip[DL]: Done driving station state, nothing else to do...
W (1940) wifi:Haven't to connect to a suitable AP now!
E (1960) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
W (1960) wifi:Haven't to connect to a suitable AP now!
E (1970) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (2010) main_task: Returned from app_main()
> W (2040) wifi:Haven't to connect to a suitable AP now!
I (2040) chip[DL]: Attempting to connect WiFi station interface
E (2040) wifi:sta is connecting, return error
E (2060) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (4810) esp_matter_core: Store the deferred attribute 0x0 of cluster 0x8 on endpoint 0x1
I (5100) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
W (5100) wifi:Haven't to connect to a suitable AP now!
I (5100) chip[DL]: Attempting to connect WiFi station interface
I (5110) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (5110) chip[DL]: Done driving station state, nothing else to do...
I (5120) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (5120) wifi:(connect)dot11_authmode:0x3, pairwise_cipher:0x3, group_cipher:0x3
I (5140) wifi:state: init -> auth (b0)
I (5140) wifi:state: auth -> assoc (0)
I (5150) wifi:Extended Capabilities length:8, subtype:0x10, 2c:3a:fd:af:ca:0e, Operating mode notification Support
I (5150) wifi:state: assoc -> run (10)
I (5160) wifi:(trc)phytype:CBW20-SGI, snr:60, maxRate:144, highestRateIdx:0
I (5160) wifi:(trc)rate(S-MCS7, schedIdx:0), ampdu(rate:S-MCS7, schedIdx(0, stop:8)), snr:60, ampduState:wait operational
I (5170) wifi:ifidx:0, rssi:-36, nf:-96, phytype(0x3, CBW20-SGI), phymode(0x3, 11bgn), max_rate:1440, he:0
I (5180) wifi:max ampdu length exponent:3(65535 bytes), mmss:0(no restriction)
I (5210) wifi:(extcap)mbssid:0, enhanced_mbssid_advertise:0, complete_nontxbssid_profiles:0, twt_responder: 0
I (5210) wifi:connected with FRITZ!Box 7530 DY, aid = 1, channel 1, BW20, bssid = 2c:3a:fd:af:ca:0e
I (5220) wifi:cipher(pairwise:0x3, group:0x3), pmf:0, security:WPA2-PSK, phy:11bgn, rssi:-36
I (5240) wifi:pm start, type: 1, itwt_start:0

I (5240) wifi:pm start, type:1, aid:0x1, trans-BSSID:2c:3a:fd:af:ca:0e, BSSID[5]:0xe, mbssid(max-indicator:0, index:0), he:0
I (5250) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (5260) wifi:set rx beacon pti, rx_bcn_pti: 10, bcn_timeout: 25000, mt_pti: 10, mt_time: 10000
I (5260) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:1, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (5270) wifi:[ADDBA]TX addba request, tid:7, dialogtoken:2, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x20)
I (5280) wifi:[ADDBA]TX addba request, tid:5, dialogtoken:3, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (5300) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (5310) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (5310) wifi:[ADDBA]RX addba response, status:0, tid:7/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (5320) wifi:[ADDBA]RX addba response, status:0, tid:5/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (5300) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (5330) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (5340) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (5350) chip[DL]: WiFi station interface connected
I (5360) chip[ZCL]: W (5360) wifi:<ba-add>idx:0, ifx:0, tid:6, TAHI:0x1000eca, TALO:0xaffd3a2c, (ssn:2, win:64, cur_ssn:2), CONF:0xc0006005
WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (5380) chip[DL]: Done driving station state, nothing else to do...
I (5380) chip[DL]: Updating advertising data
I (5390) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (5390) chip[DL]: Device already advertising, stop active advertisement and restart
I (5400) NimBLE: GAP procedure initiated: stop advertising.

I (5410) NimBLE: GAP procedure initiated: advertise;
I (5420) NimBLE: disc_mode=2
I (5420) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (5430) NimBLE:

I (6300) esp_netif_handlers: sta ip: 192.168.178.67, mask: 255.255.255.0, gw: 192.168.178.1
I (6300) chip[DL]: IP_EVENT_STA_GOT_IP
I (6310) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.178.67/255.255.255.0 gateway 192.168.178.1
I (6320) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (6320) app_main: Interface IP Address changed
I (6320) chip[DIS]: Updating services using commissioning mode 1
I (6330) chip[DIS]: CHIP minimal mDNS started advertising.
I (6350) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (6350) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D6AE8150D313F113.
I (6360) chip[DIS]: mDNS service published: _matterc._udp
I (6690) chip[DL]: IP_EVENT_GOT_IP6
I (6690) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:5632:04ff:fe07:177c
I (6700) app_main: Interface IP Address changed
I (6700) chip[DIS]: Updating services using commissioning mode 1
I (6710) chip[DIS]: CHIP minimal mDNS started advertising.
I (6720) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (6720) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D6AE8150D313F113.
I (6740) chip[DIS]: mDNS service published: _matterc._udp
I (6740) chip[SVR]: Server initialization complete
I (6750) chip[DIS]: Updating services using commissioning mode 1
I (6750) chip[DIS]: CHIP minimal mDNS started advertising.
I (6770) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (6770) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D6AE8150D313F113.
I (6780) chip[DIS]: mDNS service published: _matterc._udp
I (6790) chip[SWU]: Stopping the watchdog timer
I (6800) chip[SWU]: Starting the periodic query timer, timeout: 86400 seconds
I (6800) chip[IM]: No subscriptions to resume
I (6810) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 0 **********
I (6820) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 1 **********
I (6830) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000003 is 0 **********
I (6850) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000003 is null **********
I (7690) chip[DL]: IP_EVENT_GOT_IP6
I (7690) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fd00:0000:0000:0000:5632:04ff:fe07:177c
I (7700) ROUTE_HOOK: Hook already installed on netif, skip...
I (7700) app_main: Interface IP Address changed
I (7710) chip[DIS]: Updating services using commissioning mode 1
I (7710) chip[DIS]: CHIP minimal mDNS started advertising.
I (7730) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (7730) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D6AE8150D313F113.
I (7750) chip[DIS]: mDNS service published: _matterc._udp
I (31580) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (31580) chip[DL]: Device already advertising, stop active advertisement and restart
I (31590) NimBLE: GAP procedure initiated: stop advertising.

I (31590) NimBLE: GAP procedure initiated: advertise;
I (31600) NimBLE: disc_mode=2
I (31600) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (31610) NimBLE:

@bzbarsky-apple
Copy link
Contributor

@mulligan252 That log looks fine as far as it goes, but only shows commissionable advertising, not operational.

Might I also suggest attaching, not pasting logs, to keep the issue readable?

In any case, the chip-tool log above shows that it tries to resolve the device's IP and never manages to do that before the command timeout. Hence my suggestion to test whether raising the timeout (ideally to > 45 seconds, which is the resolution timeout) helps anything. Even if it's just seeing whether resolution then times out.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working linux needs triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mulligan252 @bzbarsky-apple