search

espressif / esp-matter

Espressif's SDK for Matter
Apache License 2.0
698 stars 158 forks source link

Google Home connection issue #145

Closed eos1d3 closed 1 year ago

eos1d3 commented 1 year ago

IDF 4.4.2 / 4.4.3

Target: ESP32C3/ESP32

Google Nest Hub2: System firmware version:324896 Cast firmware: 1.56.324896

Google Home 2.62.1.15
Google Home 2.62.80.2 Google Home 2.63.5.1-dogfood

It works with Amazon Echo 4 and can be paired and controlled. But none of any combination work with Google Home. Google Home displays:

Connecting Device to Google Home
...
Something went Wrong
Make sure you're connected to your network and try again

log from ESP32C3 (from startup to Google Home pairing)

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd5810,len:0x16b4
load:0x403cc710,len:0x930
load:0x403ce710,len:0x2d28
entry 0x403cc710
(30) boot: ESP-IDF v4.4.3 2nd stage bootloader
(30) boot: compile time 02:56:34
(30) boot: chip revision: 3
(32) boot.esp32c3: SPI Speed      : 80MHz
(37) boot.esp32c3: SPI Mode       : DIO
(41) boot.esp32c3: SPI Flash Size : 4MB
(46) boot: Enabling RNG early entropy source...
(52) boot: Partition Table:
(55) boot: ## Label            Usage          Type ST Offset   Length
(62) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
(70) boot:  1 nvs              WiFi data        01 02 00010000 00006000
(77) boot:  2 nvs_keys         NVS keys         01 04 00016000 00001000
(85) boot:  3 otadata          OTA data         01 00 00017000 00002000
(92) boot:  4 phy_init         RF data          01 01 00019000 00001000
(100) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
(107) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
(115) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
(122) boot: End of partition table
(127) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=2ec08h (191496) map
(165) esp_image: segment 1: paddr=0004ec30 vaddr=3fc91c00 size=013e8h (  5096) load
(166) esp_image: segment 2: paddr=00050020 vaddr=42000020 size=f5c9ch (1006748) map
(328) esp_image: segment 3: paddr=00145cc4 vaddr=3fc92fe8 size=02328h (  9000) load
(330) esp_image: segment 4: paddr=00147ff4 vaddr=40380000 size=11a9ch ( 72348) load
(347) esp_image: segment 5: paddr=00159a98 vaddr=50000010 size=00010h (    16) load
(353) boot: Loaded app from partition at offset 0x20000
(353) boot: Disabling RNG early entropy source...
(368) cpu_start: Pro cpu up.
(376) cpu_start: Pro cpu start user code
(376) cpu_start: cpu freq: 160000000
(376) cpu_start: Application information:
(379) cpu_start: Project name:     light
(384) cpu_start: App version:      v1.0
(388) cpu_start: Compile time:     Dec 31 2022 02:56:25
(394) cpu_start: ELF file SHA256:  dd84cad64cc3fb0f...
(400) cpu_start: ESP-IDF:          v4.4.3
(405) heap_init: Initializing. RAM available for dynamic allocation:
(413) heap_init: At 3FCA5FF0 len 00036720 (217 KiB): DRAM
(419) heap_init: At 3FCDC710 len 00002950 (10 KiB): STACK/DRAM
(425) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
(432) spi_flash: detected chip: generic
(437) spi_flash: flash io: dio
(442) sleep: Configure to isolate all GPIO pins in sleep state
(447) sleep: Enable automatic switching of GPIO sleep configuration
(454) coexist: coexist rom version 9387209
(459) cpu_start: Starting scheduler.
(485) led_driver_ws2812: Initializing light driver
(485) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
(495) app_main: Light created with endpoint_id 1
(495) esp_matter_core: Command 0x0047 on cluster 0x0300 already exists. Not creating again.
(505) pp: pp rom version: 9387209
(505) net80211: net80211 rom version: 9387209
I (525) wifi:wifi driver task: 3fcb226c, prio:23, stack:6656, core=0
(525) system_api: Base MAC address is not set
(525) system_api: read default base MAC address from EFUSE
I (535) wifi:wifi firmware version: 8cb87ff
I (535) wifi:wifi certification version: v7.0
I (535) wifi:config NVS flash: enabled
I (535) wifi:config nano formating: disabled
I (545) wifi:Init data frame dynamic rx buffer num: 32
I (545) wifi:Init management frame dynamic rx buffer num: 32
I (555) wifi:Init management short buffer num: 32
I (555) wifi:Init dynamic tx buffer num: 32
I (565) wifi:Init static tx FG buffer num: 2
I (565) wifi:Init static rx buffer size: 1600
I (575) wifi:Init static rx buffer num: 10
I (575) wifi:Init dynamic rx buffer num: 32
(575) wifi_init: rx ba win: 6
(585) wifi_init: tcpip mbox: 32
(585) wifi_init: udp mbox: 6
(585) wifi_init: tcp mbox: 6
(595) wifi_init: tcp tx win: 5744
(595) wifi_init: tcp rx win: 5744
(605) wifi_init: tcp mss: 1440
(605) wifi_init: WiFi IRAM OP enabled
(605) wifi_init: WiFi RX IRAM OP enabled
(625) chip[DL]: NVS set: chip-counters/reboot-count = 7 (0x7)
(625) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
(625) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK
(635) BTDM_INIT: BT controller compile version [421c279]
(645) phy_init: phy_version 912,d001756,Jun  2 2022,16:28:07
(675) BTDM_INIT: Bluetooth MAC: a0:76:4e:5a:c9:8a

(685) NimBLE: GAP procedure initiated: stop advertising.

(685) CHIP[DL]: BLE host-controller synced
(1185) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
(1185) NimBLE: GAP procedure initiated: advertise; 
(1185) NimBLE: disc_mode=2
(1185) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
(1195) NimBLE: 

(1205) chip[DL]: CHIPoBLE advertising started
E (1205) chip[DL]: Long dispatch time: 577 ms, for event type 2
(1215) chip[DL]: Starting ESP WiFi layer
I (1215) wifi:mode : sta (a0:76:4e:5a:c9:88)
I (1225) wifi:enable tsf
W (1225) wifi:Haven't to connect to a suitable AP now!
(1225) chip[DL]: Done driving station state, nothing else to do...
(1235) phy: chan:1,max_power:80
(1235) phy: chan:2,max_power:80
(1245) phy: chan:3,max_power:80
(1245) phy: chan:4,max_power:80
(1255) phy: chan:5,max_power:80
(1255) phy: chan:6,max_power:80
(1255) phy: chan:7,max_power:80
(1265) phy: chan:8,max_power:80
(1265) phy: chan:9,max_power:80
(1275) phy: chan:10,max_power:80
(1275) phy: chan:11,max_power:80
(1275) phy: chan:12,max_power:80
(1285) phy: chan:13,max_power:80
(1285) phy: chan:14,max_power:80
W (1295) wifi:Haven't to connect to a suitable AP now!
(1295) chip[DL]: Done driving station state, nothing else to do...
(1305) chip[SVR]: Server initializing...
(1305) chip[TS]: Last Known Good Time: 2022-12-31T02:57:26
(1315) chip[DMG]: AccessControl: initializing
(1315) chip[DMG]: Examples::AccessControlDelegate::Init
(1325) chip[DMG]: AccessControl: setting
(1335) chip[DMG]: DefaultAclStorage: initializing
(1335) chip[DMG]: DefaultAclStorage: 0 entries loaded
(1355) chip[ZCL]: Using ZAP configuration...
(1355) esp_matter_cluster: Cluster plugin init common callback
(1355) chip[DMG]: AccessControlCluster: initializing
(1365) chip[ZCL]: 0x3c10938cep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
(1375) chip[ZCL]: Initiating Admin Commissioning cluster.
E (1375) chip[ZCL]: Duplicate attribute override registration failed
(1385) chip[DIS]: Updating services using commissioning mode 1
(1395) chip[DIS]: CHIP minimal mDNS started advertising.
(1395) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
(1405) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: EEFD756C9D50A49B.
(1415) chip[DIS]: mDNS service published: _matterc._udp
(1425) chip[IN]: CASE Server enabling CASE session setups
(1435) chip[SVR]: Joining Multicast groups
(1435) chip[SVR]: Server Listening...
(1445) esp_matter_core: Dynamic endpoint 0 added
(1445) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0003's Attribute 0x0001 is 0 **********
(1455) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0x0000 is 128 **********
(1465) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0xFFFC is invalid type: 0> **********
(1475) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0005's Attribute 0x0000 is 0 **********
(1485) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0xFFFC is 1 **********
(1495) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x4003 is null **********
(1515) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
(1525) chip[ZCL]: On/Off set value: 1 1
(1525) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
(1535) chip[ZCL]: On/off already set to new value
(1545) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0002 is 1 **********
(1555) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0003 is 254 **********
(1565) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0xFFFC is 3 **********
(1575) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
(1585) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x4000 is 64 **********
(1595) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
(1605) led_driver_ws2812: led set r:0, g:0, b:0
(1615) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x4010 is null **********
(1625) esp_matter_core: Dynamic endpoint 1 added
E (1625) chip[DL]: Long dispatch time: 326 ms, for event type 2
(1635) chip[DL]: WIFI_EVENT_STA_START
(1635) phy: chan:1,max_power:80
(1645) phy: chan:2,max_power:80
(1645) phy: chan:3,max_power:80
(1655) phy: chan:4,max_power:80
(1655) phy: chan:5,max_power:80
(1655) phy: chan:6,max_power:80
(1665) phy: chan:7,max_power:80
(1665) phy: chan:8,max_power:80
(1675) phy: chan:9,max_power:80
(1675) phy: chan:10,max_power:80
(1675) phy: chan:11,max_power:80
(1685) phy: chan:12,max_power:80
(1685) phy: chan:13,max_power:80
(1695) phy: chan:14,max_power:80
W (1695) wifi:Haven't to connect to a suitable AP now!
(1695) chip[DL]: Done driving station state, nothing else to do...
(1705) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
(1715) chip[DL]: Device already advertising, stop active advertisement and restart
(1725) NimBLE: GAP procedure initiated: stop advertising.

(1735) NimBLE: GAP procedure initiated: advertise; 
(1735) NimBLE: disc_mode=2
(1735) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
(1745) NimBLE: 

(1755) app_main: Commissioning window opened
(1755) led_driver_ws2812: led set r:0, g:0, b:0
(1765) led_driver_ws2812: led set r:0, g:0, b:0
(1765) led_driver_ws2812: led set r:25, g:20, b:16
> (31395) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
(31395) chip[DL]: Device already advertising, stop active advertisement and restart
(31405) NimBLE: GAP procedure initiated: stop advertising.

(31405) NimBLE: GAP procedure initiated: advertise; 
(31415) NimBLE: disc_mode=2
(31415) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
(31425) NimBLE: 

(65245) chip[DL]: BLE GAP connection established (con 1)
(65255) chip[DL]: CHIPoBLE advertising stopped
(66625) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(66625) chip[BLE]: local and remote recv window sizes = 5
(66635) chip[BLE]: selected BTP version 4
(66635) chip[BLE]: using BTP fragment sizes rx 128 / tx 128.
(66665) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1
(66665) chip[DL]: CHIPoBLE subscribe received
(66665) NimBLE: GATT procedure initiated: indicate; 
(66675) NimBLE: att_handle=14

(66775) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(66775) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(66795) chip[EM]: >>> [E:33870r M:95793021] (U) Msg RX from 0:684E3E8C83C146E2 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
(66805) chip[EM]:  [E:33870r M:32086171] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
(66815) chip[IN]: (U) Sending msg 32086171 to IP address 'BLE'
(66815) NimBLE: GATT procedure initiated: indicate; 
(66835) NimBLE: att_handle=14

(67045) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(67045) NimBLE: GATT procedure initiated: indicate; 
(67055) NimBLE: att_handle=14

(67225) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(67225) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(67245) chip[EM]: >>> [E:33870r M:95793022] (U) Msg RX from 0:684E3E8C83C146E2 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
(68075) chip[EM]:  [E:33870r M:32086172] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
(68085) chip[IN]: (U) Sending msg 32086172 to IP address 'BLE'
(68095) NimBLE: GATT procedure initiated: indicate; 
(68095) NimBLE: att_handle=14

E (68105) chip[DL]: Long dispatch time: 864 ms, for event type 7
(68175) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(68175) NimBLE: GATT procedure initiated: indicate; 
(68185) NimBLE: att_handle=14

(68305) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(68305) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(68325) chip[EM]: >>> [E:33870r M:95793023] (U) Msg RX from 0:684E3E8C83C146E2 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
(68335) chip[EM]:  [E:33870r M:32086173] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
(68345) chip[IN]: (U) Sending msg 32086173 to IP address 'BLE'
(68345) NimBLE: GATT procedure initiated: indicate; 
(68355) NimBLE: att_handle=14

(68365) chip[SC]: SecureSession[0x3fc98d40]: Moving from state 'kEstablishing' --> 'kActive'
(68375) chip[SVR]: Commissioning completed session establishment step
(68375) chip[DIS]: Updating services using commissioning mode 0
(68385) chip[DIS]: CHIP minimal mDNS started advertising.
(68385) chip[SVR]: Device completed Rendezvous process
(68395) app_main: Commissioning session started
(68405) app_main: Commissioning window closed
(68445) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(68445) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(68455) chip[EM]: >>> [E:33871r M:240318562] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(68475) chip[EM]:  [E:33871r M:164083411] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(68475) chip[IN]: (S) Sending msg 164083411 on secure session with LSID: 13228
(68485) NimBLE: GATT procedure initiated: indicate; 
(68485) NimBLE: att_handle=14

(68665) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(68665) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(68685) chip[EM]: >>> [E:33872r M:240318563] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(68695) chip[EM]:  [E:33872r M:164083412] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(68695) chip[IN]: (S) Sending msg 164083412 on secure session with LSID: 13228
(68715) NimBLE: GATT procedure initiated: indicate; 
(68725) NimBLE: att_handle=14

(68985) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(68985) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(68995) chip[EM]: >>> [E:33873r M:240318564] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(69015) chip[EM]:  [E:33873r M:164083413] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(69015) chip[IN]: (S) Sending msg 164083413 on secure session with LSID: 13228
(69025) NimBLE: GATT procedure initiated: indicate; 
(69035) NimBLE: att_handle=14

(69115) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69115) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(69135) chip[EM]: >>> [E:33874r M:240318565] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(69145) chip[EM]:  [E:33874r M:164083414] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(69145) chip[IN]: (S) Sending msg 164083414 on secure session with LSID: 13228
(69165) NimBLE: GATT procedure initiated: indicate; 
(69175) NimBLE: att_handle=14

(69255) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69255) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(69265) chip[EM]: >>> [E:33875r M:240318566] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(69285) chip[EM]:  [E:33875r M:164083415] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(69285) chip[IN]: (S) Sending msg 164083415 on secure session with LSID: 13228
(69295) NimBLE: GATT procedure initiated: indicate; 
(69305) NimBLE: att_handle=14

(69435) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69435) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(69445) chip[EM]: >>> [E:33876r M:240318567] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(69465) chip[EM]:  [E:33876r M:164083416] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(69465) chip[IN]: (S) Sending msg 164083416 on secure session with LSID: 13228
(69475) NimBLE: GATT procedure initiated: indicate; 
(69475) NimBLE: att_handle=14

(69565) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69565) NimBLE: GATT procedure initiated: indicate; 
(69575) NimBLE: att_handle=14

(69655) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69655) NimBLE: GATT procedure initiated: indicate; 
(69665) NimBLE: att_handle=14

(69885) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(69885) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(69895) chip[EM]: >>> [E:33877r M:240318568] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(69915) chip[EM]:  [E:33877r M:164083417] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(69915) chip[IN]: (S) Sending msg 164083417 on secure session with LSID: 13228
(69925) NimBLE: GATT procedure initiated: indicate; 
(69935) NimBLE: att_handle=14

(70065) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(70965) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(70965) chip[EM]: >>> [E:33878r M:240318569] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
(70975) chip[EM]:  [E:33878r M:164083418] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
(70995) chip[IN]: (S) Sending msg 164083418 on secure session with LSID: 13228
(70995) NimBLE: GATT procedure initiated: indicate; 
(71005) NimBLE: att_handle=14

(71095) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71095) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(71115) chip[EM]: >>> [E:33878r M:240318570] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(71125) esp_matter_command: Received command 0x0000 for enpoint 0x0000's cluster 0x00000030
(71125) chip[FS]: GeneralCommissioning: Received ArmFailSafe (120s)
(71135) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 1 **********
(71155) chip[EM]:  [E:33878r M:164083419] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(71165) chip[IN]: (S) Sending msg 164083419 on secure session with LSID: 13228
(71165) NimBLE: GATT procedure initiated: indicate; 
(71175) NimBLE: att_handle=14

(71275) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71275) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(71295) chip[EM]: >>> [E:33879r M:240318571] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
(71305) chip[EM]:  [E:33879r M:164083420] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(71305) chip[IN]: (S) Sending msg 164083420 on secure session with LSID: 13228
(71325) NimBLE: GATT procedure initiated: indicate; 
(71335) NimBLE: att_handle=14

(71415) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71415) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(71425) chip[EM]: >>> [E:33880r M:240318572] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
(71445) chip[EM]:  [E:33880r M:164083421] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
(71445) chip[IN]: (S) Sending msg 164083421 on secure session with LSID: 13228
(71455) NimBLE: GATT procedure initiated: indicate; 
(71465) NimBLE: att_handle=14

(71545) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71545) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(71565) chip[EM]: >>> [E:33880r M:240318573] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(71575) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x00000030
(71575) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
(71585) chip[DL]: NVS set: chip-config/country-code = "US"
(71595) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 1 **********
(71605) chip[EM]:  [E:33880r M:164083422] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(71615) chip[IN]: (S) Sending msg 164083422 on secure session with LSID: 13228
(71625) NimBLE: GATT procedure initiated: indicate; 
(71625) NimBLE: att_handle=14

(71725) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71725) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(71745) chip[EM]: >>> [E:33881r M:240318574] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(71755) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x0000003E
(71755) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
(71775) chip[EM]:  [E:33881r M:164083423] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(71785) chip[IN]: (S) Sending msg 164083423 on secure session with LSID: 13228
(71785) NimBLE: GATT procedure initiated: indicate; 
(71795) NimBLE: att_handle=14

(71865) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71865) NimBLE: GATT procedure initiated: indicate; 
(71875) NimBLE: att_handle=14

(71955) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(71955) NimBLE: GATT procedure initiated: indicate; 
(71965) NimBLE: att_handle=14

(72045) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72045) NimBLE: GATT procedure initiated: indicate; 
(72055) NimBLE: att_handle=14

(72135) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72135) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(72145) NimBLE: GATT procedure initiated: indicate; 
(72145) NimBLE: att_handle=14

(72225) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72225) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(72235) chip[EM]: >>> [E:33882r M:240318575] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(72255) esp_matter_command: Received command 0x0002 for enpoint 0x0000's cluster 0x0000003E
(72255) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
(72265) chip[EM]:  [E:33882r M:164083424] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(72275) chip[IN]: (S) Sending msg 164083424 on secure session with LSID: 13228
(72285) NimBLE: GATT procedure initiated: indicate; 
(72295) NimBLE: att_handle=14

(72355) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72355) NimBLE: GATT procedure initiated: indicate; 
(72365) NimBLE: att_handle=14

(72445) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72445) NimBLE: GATT procedure initiated: indicate; 
(72455) NimBLE: att_handle=14

(72535) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72535) NimBLE: GATT procedure initiated: indicate; 
(72545) NimBLE: att_handle=14

(72625) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72625) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(72645) NimBLE: GATT procedure initiated: indicate; 
(72645) NimBLE: att_handle=14

(72715) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(72715) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(72735) chip[EM]: >>> [E:33883r M:240318576] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(72745) esp_matter_command: Received command 0x0000 for enpoint 0x0000's cluster 0x0000003E
(72745) chip[ZCL]: OpCreds: Received an AttestationRequest command
(72925) chip[ZCL]: OpCreds: AttestationRequest successful.
(72935) chip[EM]:  [E:33883r M:164083425] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(72945) chip[IN]: (S) Sending msg 164083425 on secure session with LSID: 13228
(72945) NimBLE: GATT procedure initiated: indicate; 
(72955) NimBLE: att_handle=14

E (72955) chip[DL]: Long dispatch time: 226 ms, for event type 7
(73075) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73075) NimBLE: GATT procedure initiated: indicate; 
(73085) NimBLE: att_handle=14

(73215) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73215) NimBLE: GATT procedure initiated: indicate; 
(73225) NimBLE: att_handle=14

(73305) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73305) NimBLE: GATT procedure initiated: indicate; 
(73315) NimBLE: att_handle=14

(73395) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73395) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(73405) NimBLE: GATT procedure initiated: indicate; 
(73405) NimBLE: att_handle=14

(73485) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73485) NimBLE: GATT procedure initiated: indicate; 
(73495) NimBLE: att_handle=14

(73575) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(73575) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(73585) chip[EM]: >>> [E:33884r M:240318577] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
(73605) esp_matter_command: Received command 0x0004 for enpoint 0x0000's cluster 0x0000003E
(73605) chip[ZCL]: OpCreds: Received a CSRRequest command
(73945) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
(74115) chip[ZCL]: OpCreds: CSRRequest successful.
(74115) chip[EM]:  [E:33884r M:164083426] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(74125) chip[IN]: (S) Sending msg 164083426 on secure session with LSID: 13228
(74125) NimBLE: GATT procedure initiated: indicate; 
(74135) NimBLE: att_handle=14

E (74145) chip[DL]: Long dispatch time: 555 ms, for event type 7
(74205) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(74205) NimBLE: GATT procedure initiated: indicate; 
(74215) NimBLE: att_handle=14

(74335) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(74335) NimBLE: GATT procedure initiated: indicate; 
(74345) NimBLE: att_handle=14

(74605) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(74605) NimBLE: GATT procedure initiated: indicate; 
(74615) NimBLE: att_handle=14

(74695) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
(74695) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12
(76585) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0
(76585) chip[DL]: CHIPoBLE unsubscribe received
(76595) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
(76585) chip[BLE]: Releasing end point's BLE connection back to application.
(191135) chip[FS]: Fail-safe timer expired
E (191135) chip[SVR]: Failsafe timer expired
(191135) chip[SC]: SecureSession[0x3fc98d40]: Moving from state 'kActive' --> 'kPendingEviction'
E (191155) chip[SVR]: Commissioning failed (attempt 1): 32
(191165) chip[DIS]: Updating services using commissioning mode 1
(191165) chip[DIS]: CHIP minimal mDNS started advertising.
(191175) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
(191175) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: EEFD756C9D50A49B.
(191195) chip[DIS]: mDNS service published: _matterc._udp
E (191205) chip[ZCL]: OpCreds: Got FailSafeTimerExpired
E (191205) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
(191215) chip[TS]: Pending Last Known Good Time: 2022-12-31T02:57:26
(191215) chip[TS]: Previous Last Known Good Time: 2022-12-31T02:57:26
(191225) chip[TS]: Reverted Last Known Good Time to previous value
(191235) esp_matter_attribute: ********** Endpoint 0x0000's Cluster 0x0030's Attribute 0x0000 is 0 **********
(191255) app_main: Commissioning failed, fail safe timer expired
E (191255) chip[DL]: Long dispatch time: 113 ms, for event type 32782
(191265) chip[FS]: Fail-safe cleanly disarmed
(191265) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
(191275) NimBLE: GAP procedure initiated: advertise; 
(191275) NimBLE: disc_mode=2
(191275) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
(191285) NimBLE: 

(191305) chip[DL]: CHIPoBLE advertising started
(191305) app_main: Commissioning window opened
(221165) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
(221165) chip[DL]: Device already advertising, stop active advertisement and restart
(221175) NimBLE: GAP procedure initiated: stop advertising.

(221185) NimBLE: GAP procedure initiated: advertise; 
(221195) NimBLE: disc_mode=2
(221195) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
(221205) NimBLE: 

jonsmirl commented 1 year ago

Google Home is currently broken from the Google side of things for all of the test device IDs. Everyone is waiting for them to fix it.

eos1d3 commented 1 year ago

Oh... Thanks a lot for the information.

BTW, where to know when it is fixed?

jonsmirl commented 1 year ago

watch for an update on your Google Home, the version number will change

dhrishi commented 1 year ago

@eos1d3 @jonsmirl WIth the latest update from Google, commissioning is again successful with test devices. Please update your hub and the app and give it a try.

eos1d3 commented 1 year ago

@dhrishi Do you mean Google Home 2.62.80.2? In my area, I am still seeing Google Home 2.62.1.9 in Play Store. My Nest Hub 2 firmware is 324896. Is it OK?

dhrishi commented 1 year ago

@eos1d3 Google Home App: 2.62.1.15 , Nest Hub: 1.56.324896, these versions work at our end. Although, the fix is on the backend side as per Google, and hence you should be able to commission successfully too (without any update). Let me know if that doesn't happen

eos1d3 commented 1 year ago

@dhrishi

There is a good news. Google Home 2.62.1.15 finally works. So both Google Home and Alexa are working.

And I just deleted the device in Alexa and using Google Home to share the device to it, it works too! It is very nice.

And there can be a small bug in Google Home. When using Google Home, I have 2.4G and 5G enabled with different SSID names. My mobile phone is using 5G, I saw console saying it could not connect to 5G network. Of course it is normal. But when using Alaxa to pair, it is smarter and will prompt which SSID to use. I think it is Google Home's bug?

jonsmirl commented 1 year ago

Do you have the 2.4G Network SSID/PW saved in Android?

eos1d3 commented 1 year ago

Yes. It has both sets of passwords. Once I got the problem, I changed my mobile phone to 2.4G and it works. It is strange that it should ask which SSID to use.

dhrishi commented 1 year ago

And there can be a small bug in Google Home. When using Google Home, I have 2.4G and 5G enabled with different SSID names. My mobile phone is using 5G, I saw console saying it could not connect to 5G network. Of course it is normal. But when using Alaxa to pair, it is smarter and will prompt which SSID to use. I think it is Google Home's bug?

We will check this with Google.

Thanks for the confirmation. I will close this issue as the original problem is now solved.