topic Re: commissioning is incomplete by google home app in Smart Home Developer Forum

commissioning is incomplete by google home app

mt0msk — Wed, 01 Feb 2023 00:34:34 GMT

Hi,

I try commissioning the Matter cluster as below examples from Google Home App.

https://github.com/project-chip/connectedhomeip/tree/v1.0.0.2/examples/lock-app/infineon/psoc6

https://github.com/project-chip/connectedhomeip/tree/v1.0.0.2/examples/lighting-app/nrfconnect

https://github.com/project-chip/connectedhomeip/tree/v1.0.0.2/examples/lighting-app/esp32

However, Google Home App did not finish commissioning normally, I got an error.

Apple Home could finish commissioning normally and control clusters.

So, I judge that there is no problem with the Matter clusters.

Would you please help me?

Environment

Phone : Pixel 7 Pro

Google Home App : 2.63.1.12

Google Nest Hub Gen2

Firmware : 324896

Cast Firmware : 1.56.324896

Matter SDK : commit 4088a77f557e8571a39338fad51a1d8eb0131d79 (HEAD, tag: v1.0.0.2)

Re: commissioning is incomplete by google home app

mt0msk — Wed, 01 Feb 2023 00:41:12 GMT

Detailed information

PSoC6

When "CHIP:IN: Clearing BLE pending packets." shows, Home App shows error message.

CHIP:P6: ==================================================

CHIP:P6: chip-p6-lock-example starting Version 1

CHIP:P6: ==================================================

CHIP:P6: chip-p6-lock-example starting Version 1

CHIP:P6: ==================================================

CHIP:DL: BLEManagerImpl::Init() complete
CHIP:DL: EnableStationMode
CHIP:DL: WiFi station mode change: Disabled -> Disabled
CHIP:DL: Starting P6 WiFi layer
WLAN MAC Address : 18:48:CA:88:45:8E
WLAN Firmware : wl0: Apr 12 2022 20:39:36 version 13.10.271.287 (760d561 CY) FWID 01-b438e2a0
WLAN CLM : API: 18.2 Data: 9.10.0 Compiler: 1.36.1 ClmImport: 1.34.1 Creation: 2021-04-26 04:01:15
WHD VERSION : v2.4.0 : v2.4.0 : GCC 10.3 : 2022-08-04 17:12:02 +0800
CHIP:DL: EnableStationMode
CHIP:DL: Done driving station state, nothing else to do...
CHIP:DL: SetAPMode
CHIP:DL: Setting device name to : "P6_LOCK"
CHIP:P6: Starting Platform Manager Event Loop
CHIP:DL: CHIP task running
CHIP:DL: Starting P6 WiFi layer
CHIP:DL: EnableStationMode
CHIP:P6: Current Software Version: 1
CHIP:DL: Done driving station state, nothing else to do...
CHIP:SVR: Server initializing...
CHIP:FP: Initializing FabricTable from persistent storage
CHIP:TS: Last Known Good Time: 2023-01-31T15:39:19
CHIP:DMG: AccessControl: initializing
CHIP:DMG: Examples::AccessControlDelegate::Init
CHIP:DMG: AccessControl: setting
CHIP:DMG: DefaultAclStorage: initializing
CHIP:DMG: DefaultAclStorage: 0 entries loaded
CHIP:IN: UDP::Init bind&listen port=5540
CHIP:IN: UDP::Init bound to port=5540
CHIP:IN: UDP::Init bind&listen port=5540
CHIP:IN: UDP::Init bound to port=5540
CHIP:IN: BLEBase::Init - setting/overriding transport
CHIP:IN: TransportMgr initialized
CHIP:ZCL: Using ZAP configuration...
CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0
CHIP:DMG: Failed to read stored attribute (0, 0x0000_002B, 0x0000_0000: a0
CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0
CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: a0
CHIP:DMG: Failed to read stored attribute (1, 0x0000_0101, 0x0000_0000: a0
CHIP:DMG: AccessControlCluster: initializing
CHIP:ZCL: Initiating Admin Commissioning cluster.
CHIP:ZCL: Door Lock server initialized
CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 87b0f38
CHIP:ZCL: Cluster callback: 0x0000_0030
CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot
CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to 3ab4f561
CHIP:EVL: LogEvent event number: 0x0000000000040000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000043D
CHIP:ZCL: DeviceInfoProvider is not registered
CHIP:ZCL: Trying to write invalid Calendar Type
CHIP:ZCL: Failed to write calendar type with error: 0x87
CHIP:DMG: Endpoint 1, Cluster 0x0000_0003 update version to 8c352ff
CHIP:ZCL: Cluster callback: 0x0000_0003
CHIP:IN: SecureSession[0x8029c00]: Allocated Type:1 LSID:61823
CHIP:SC: Assigned local session key ID 61823
CHIP:SC: Waiting for PBKDF param request
CHIP:DIS: Updating services using commissioning mode 1
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:DL: Using wifi MAC for hostname
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
CHIP:DIS: Responding with _matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
CHIP:DIS: Responding with _S15._sub._matterc._udp.local
CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
CHIP:DIS: Responding with _CM._sub._matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 7BFBEA83DAFFF178.
CHIP:DIS: mDNS service published: _matterc._udp
CHIP:DIS: Updating services using commissioning mode 1
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:DL: Using wifi MAC for hostname
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
CHIP:DIS: Responding with _matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
CHIP:DIS: Responding with _S15._sub._matterc._udp.local
CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
CHIP:DIS: Responding with _CM._sub._matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 7BFBEA83DAFFF178.
CHIP:DIS: mDNS service published: _matterc._udp
CHIP:IN: CASE Server enabling CASE session setups
CHIP:IN: SecureSession[0x8029cb8]: Allocated Type:2 LSID:61824
CHIP:SC: Allocated SecureSession (0x8029cb8) - waiting for Sigma1 msg
CHIP:SVR: Joining Multicast groups
CHIP:ZCL: Emitting StartUp event
CHIP:EVL: LogEvent event number: 0x0000000000040001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000522
CHIP:SVR: Server Listening...
CHIP:DL: Long dispatch time: 373 ms, for event type 2
CHIP:DL: Device Configuration:
CHIP:DL: Serial Number: TEST_SN
CHIP:DL: Vendor Id: 65521 (0xFFF1)
CHIP:DL: Product Id: 32774 (0x8006)
CHIP:DL: Hardware Version: 43012
CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
CHIP:DL: Manufacturing Date: (not set)
CHIP:DL: Device Type: 10 (0xA)
CHIP:SVR: SetupQRCode: [MT:8IXS142C00KA0648G00]
CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00
CHIP:SVR: Manual pairing code: [34970112332]
CHIP:P6: App Task started
CHIP:DL: CHIPoBLE advertising started
CHIP:DL: BLEManagerImpl::SetAdvertisingData err:Success

Re: commissioning is incomplete by google home app

mt0msk — Wed, 01 Feb 2023 00:44:52 GMT

PSoC6

Commissioning

CHIP:DL: Failed to find CHIPoBLEConState
CHIP:DL: BLE GATT connection up (con 32768)
CHIP:BLE: local and remote recv window sizes = 5
CHIP:BLE: selected BTP version 4
CHIP:BLE: using BTP fragment sizes rx 128 / tx 128.
CHIP:DL: Write received for CHIPoBLE RX characteristic con:8000 handle:000c len:2
CHIP:DL: CHIPoBLE subscribe received
CHIP:IN: BLE EndPoint 0x802ef68 Connection Complete
CHIP:EM: >>> [E:894r M:226912896] (U) Msg RX from 0:656C0CE0C5C54B36 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
CHIP:EM: Handling via exchange: 894r, Delegate: 0x802deec
CHIP:SC: Received PBKDF param request
CHIP:SC: Peer assigned session ID 3764
CHIP:SC: Found MRP parameters in the message
CHIP:EM: <<< [E:894r M:253599446] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
CHIP:IN: (U) Sending msg 253599446 to IP address 'BLE'
CHIP:SC: Sent PBKDF param response
CHIP:EM: >>> [E:894r M:226912897] (U) Msg RX from 0:656C0CE0C5C54B36 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
CHIP:EM: Found matching exchange: 894r, Delegate: 0x802deec
CHIP:SC: Received spake2p msg1
CHIP:EM: <<< [E:894r M:253599447] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
CHIP:IN: (U) Sending msg 253599447 to IP address 'BLE'
CHIP:SC: Sent spake2p msg2
CHIP:DL: Long dispatch time: 1754 ms, for event type 7
CHIP:EM: >>> [E:894r M:226912898] (U) Msg RX from 0:656C0CE0C5C54B36 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
CHIP:EM: Found matching exchange: 894r, Delegate: 0x802deec
CHIP:SC: Received spake2p msg3
CHIP:SC: Sending status report. Protocol code 0, exchange 894
CHIP:EM: <<< [E:894r M:253599448] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
CHIP:IN: (U) Sending msg 253599448 to IP address 'BLE'
CHIP:SC: SecureSession[0x8029c00]: Moving from state 'kEstablishing' --> 'kActive'
CHIP:IN: SecureSession[0x8029c00]: Activated - Type:1 LSID:61823
CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:61823 PSID:3764!
CHIP:SVR: Commissioning completed session establishment step
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:SVR: Device completed Rendezvous process
CHIP:DL: CHIPoBLE stop advertising
CHIP:EM: >>> [E:895r M:224846545] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 895r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 28, Attribute 2 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 37 bytes)...
CHIP:EM: <<< [E:895r M:267016839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016839 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:896r M:224846546] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 896r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 28, Attribute 4 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 37 bytes)...
CHIP:EM: <<< [E:896r M:267016840] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016840 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:897r M:224846547] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 897r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 3e, Attribute 2 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 36 bytes)...
CHIP:EM: <<< [E:897r M:267016841] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016841 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:898r M:224846548] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 898r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 3e, Attribute 3 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 36 bytes)...
CHIP:EM: <<< [E:898r M:267016842] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016842 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:899r M:224846549] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 899r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 3e, Attribute 1 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 36 bytes)...
CHIP:EM: <<< [E:899r M:267016843] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016843 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:900r M:224846550] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 900r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 1d, Attribute 1 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 624 bytes)...
CHIP:EM: <<< [E:900r M:267016844] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016844 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:901r M:224846551] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 901r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 31, Attribute fffc is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 37 bytes)...
CHIP:EM: <<< [E:901r M:267016845] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016845 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:902r M:224846552] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
CHIP:EM: Handling via exchange: 902r, Delegate: 0x801f58c
CHIP:DMG: Got Timed Request with timeout 10000: handler 0x801f988 exchange 902r
CHIP:EM: <<< [E:902r M:267016846] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
CHIP:IN: (S) Sending msg 267016846 on secure session with LSID: 61823
CHIP:DMG: Timed Request time limit 0x0000000000010A7C: handler 0x801f988 exchange 902r
CHIP:EM: >>> [E:902r M:224846553] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Found matching exchange: 902r, Delegate: 0x801f988
CHIP:DMG: Timed following action arrived at 0x000000000000E3B3: handler 0x801f988 exchange 902r
CHIP:DMG: Handing timed invoke to IM engine: handler 0x801f988 exchange 902r
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
CHIP:FS: GeneralCommissioning: Received ArmFailSafe (120s)
CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 87b0f39
CHIP:ZCL: Cluster callback: 0x0000_0030
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:902r M:267016847] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016847 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:EM: >>> [E:903r M:224846554] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 903r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 30, Attribute 3 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 36 bytes)...
CHIP:EM: <<< [E:903r M:267016848] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016848 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
CHIP:EM: >>> [E:904r M:224846555] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
CHIP:EM: Handling via exchange: 904r, Delegate: 0x801f58c
CHIP:DMG: Got Timed Request with timeout 10000: handler 0x801f988 exchange 904r
CHIP:EM: <<< [E:904r M:267016849] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
CHIP:IN: (S) Sending msg 267016849 on secure session with LSID: 61823
CHIP:DMG: Timed Request time limit 0x0000000000010C40: handler 0x801f988 exchange 904r
CHIP:EM: >>> [E:904r M:224846556] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Found matching exchange: 904r, Delegate: 0x801f988
CHIP:DMG: Timed following action arrived at 0x000000000000E577: handler 0x801f988 exchange 904r
CHIP:DMG: Handing timed invoke to IM engine: handler 0x801f988 exchange 904r
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 87b0f3a
CHIP:ZCL: Cluster callback: 0x0000_0030
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:904r M:267016850] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016850 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:EM: >>> [E:905r M:224846557] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Handling via exchange: 905r, Delegate: 0x801f58c
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
CHIP:ZCL: OpCreds: Certificate Chain request received for DAC
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:905r M:267016851] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016851 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:EM: >>> [E:906r M:224846558] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Handling via exchange: 906r, Delegate: 0x801f58c
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
CHIP:ZCL: OpCreds: Certificate Chain request received for PAI
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:906r M:267016852] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016852 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:EM: >>> [E:907r M:224846559] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Handling via exchange: 907r, Delegate: 0x801f58c
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
CHIP:ZCL: OpCreds: Received an AttestationRequest command
CHIP:ZCL: OpCreds: AttestationRequest successful.
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:907r M:267016853] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016853 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:DL: Long dispatch time: 411 ms, for event type 7
CHIP:EM: >>> [E:908r M:224846560] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: Handling via exchange: 908r, Delegate: 0x801f58c
CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
CHIP:ZCL: OpCreds: Received a CSRRequest command
CHIP:ZCL: OpCreds: Finding fabric with fabricIndex 0x0
CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded
CHIP:ZCL: OpCreds: CSRRequest successful.
CHIP:DMG: Command handler moving to [ Preparing]
CHIP:DMG: Command handler moving to [AddingComm]
CHIP:DMG: Command handler moving to [AddedComma]
CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
CHIP:EM: <<< [E:908r M:267016854] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 267016854 on secure session with LSID: 61823
CHIP:DMG: Command handler moving to [CommandSen]
CHIP:DMG: Command handler moving to [AwaitingDe]
CHIP:DL: Long dispatch time: 1114 ms, for event type 7
CHIP:DL: BLE GATT connection closed (con 32768, reason 19)
CHIP:IN: Clearing BLE pending packets.

Re: commissioning is incomplete by google home app

mt0msk — Wed, 01 Feb 2023 00:46:51 GMT

PSoC6

Commissioning failed, restart advertising.

CHIP:FS: Fail-safe timer expired
CHIP:SVR: Failsafe timer expired
CHIP:IN: SecureSession[0x8029c00]: MarkForEviction Type:1 LSID:61823
CHIP:SC: SecureSession[0x8029c00]: Moving from state 'kActive' --> 'kPendingEviction'
CHIP:IN: SecureSession[0x8029c00]: Released - Type:1 LSID:61823
CHIP:SVR: Commissioning failed (attempt 1): 32
CHIP:IN: SecureSession[0x8029c00]: Allocated Type:1 LSID:61825
CHIP:SC: Assigned local session key ID 61825
CHIP:SC: Waiting for PBKDF param request
CHIP:DIS: Updating services using commissioning mode 1
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:DL: Using wifi MAC for hostname
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
CHIP:DIS: Responding with _matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with 8E4588CA4818.local
CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
CHIP:DIS: Responding with _S15._sub._matterc._udp.local
CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
CHIP:DIS: Responding with _CM._sub._matterc._udp.local
CHIP:DIS: Responding with 7BFBEA83DAFFF178._matterc._udp.local
CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 7BFBEA83DAFFF178.
CHIP:DIS: mDNS service published: _matterc._udp
CHIP:ZCL: OpCreds: Got FailSafeTimerExpired
CHIP:ZCL: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
CHIP:TS: Pending Last Known Good Time: 2023-01-31T15:39:19
CHIP:TS: Previous Last Known Good Time: 2023-01-31T15:39:19
CHIP:TS: Reverted Last Known Good Time to previous value
CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 87b0f3b
CHIP:ZCL: Cluster callback: 0x0000_0030
CHIP:ZCL: Failsafe timeout, tell platform driver to revert network credentials.
CHIP:DL: Long dispatch time: 152 ms, for event type 32782
CHIP:FS: Fail-safe cleanly disarmed
CHIP:DL: CHIPoBLE advertising started
CHIP:DL: BLEManagerImpl::SetAdvertisingData err:Success

Re: commissioning is incomplete by google home app

mt0msk — Wed, 08 Feb 2023 06:08:13 GMT

I checked log again.

CHIP:SC: SecureSession[0x8029c00]: Moving from state 'kEstablishing' --> 'kActive' ,then, type 0001 occurs.
As my understanding, type 0001 means error.

CHIP:SC: SecureSession[0x8029c00]: Moving from state 'kEstablishing' --> 'kActive'
CHIP:IN: SecureSession[0x8029c00]: Activated - Type:1 LSID:61823
CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:61823 PSID:3764!
CHIP:SVR: Commissioning completed session establishment step
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: CHIP minimal mDNS started advertising.
CHIP:SVR: Device completed Rendezvous process
CHIP:DL: CHIPoBLE stop advertising
CHIP:EM: >>> [E:895r M:224846545] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: Handling via exchange: 895r, Delegate: 0x801f58c
CHIP:IM: Received Read request
CHIP:DMG: IM RH moving to [GeneratingReports]
CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
CHIP:DMG: <RE:Run> Cluster 28, Attribute 2 is dirty
CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
CHIP:DMG: <RE> Sending report (payload has 37 bytes)...
CHIP:EM: <<< [E:895r M:267016839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 267016839 on secure session with LSID: 61823
CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
CHIP:DMG: IM RH moving to [AwaitingDestruction]
CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet

Re: commissioning is incomplete by google home app

sipriyadarshi — Wed, 15 Feb 2023 19:53:23 GMT

Hi ,

Is it possible for you to translate the error message you are encountering in English ? Also, could please share some details about what these logs are for and how are you obtaining these logs ?

Re: commissioning is incomplete by google home app

mt0msk — Thu, 16 Feb 2023 12:08:20 GMT

Hi,

I translate the error message as below.

Something went wrong
Make sure you're connected to your network and try again

Regarding Log,

I build lighting-app cluster from Matter SDK as below and flash to PSoC6.

And, PSoC6 connects PC via USB and obtain log by serial terminal (e.g. PuTTY, Teraterm pro or Minicom)

https://github.com/project-chip/connectedhomeip/tree/v1.0.0.2/examples/lighting-app/infineon/psoc6

I can get log about ESP32.

ESP32's log is same as PSoC6's log.

https://github.com/project-chip/connectedhomeip/tree/v1.0.0.2/examples/lighting-app/esp32

Re: commissioning is incomplete by google home app

sipriyadarshi — Wed, 22 Mar 2023 16:22:42 GMT

Could you provide the following details :

Did you configure the developer center console ?
Can you get the following two filters from the phone logcat :
- grep "MatterCommissioner" $phonelog
- grep "SetupDevice" $phonelog | grep -A 20 "Commissioning failed"

Re: commissioning is incomplete by google home app

mt0msk — Tue, 20 Jun 2023 05:48:08 GMT

Thank you for your reply.

I resolved.
I added cluster's vendor / product ID to google developer console.