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.

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

Unable to pair matter device since 16th dec update #61

Closed
lpfsue opened this issue Dec 16, 2022 · 23 comments
Closed

Unable to pair matter device since 16th dec update #61

lpfsue opened this issue Dec 16, 2022 · 23 comments

Comments

@lpfsue
Copy link

lpfsue commented Dec 16, 2022

I have a custom matter device based on v1.0 (using 0xfff1 as vendor and 0x8000 as product, also registered as device in the dev console). Previously I was able to pair the device but since the update yesterday/this week the pairing fails with the following message on logcat:

12-16 14:28:09.704 24297 24297 I MatterCommissioner: Retrieved DAC chain. [CONTEXT service_id=336 ]
12-16 14:28:09.704 24297 24476 D EM      : Flushed pending ack for MessageCounter:85930631 on exchange 36107i
12-16 14:28:09.705 24297 24297 D DMG     : ICR moving to [AddingComm]
12-16 14:28:09.705 24297 24297 D DMG     : ICR moving to [AddedComma]
12-16 14:28:09.705 24297 24297 D EM      : <<< [E:36108i M:35017989] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
12-16 14:28:09.705 24297 24297 D IN      : (S) Sending msg 35017989 on secure session with LSID: 25824
12-16 14:28:09.705 24297 24297 D DMG     : ICR moving to [CommandSen]
12-16 14:28:09.710 24297 24476 D EM      : >>> [E:36108i M:85930632 (Ack:35017989)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
12-16 14:28:09.710 24297 24476 D EM      : Found matching exchange: 36108i, Delegate: 0x714d244108
12-16 14:28:09.710 24297 24476 D EM      : Rxd Ack; Removing MessageCounter:35017989 from Retrans Table on exchange 36108i
12-16 14:28:09.710 24297 24476 D DMG     : ICR moving to [ResponseRe]
12-16 14:28:09.710 24297 24476 D DMG     : Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
12-16 14:28:09.711 24297 24476 D DMG     : ICR moving to [AwaitingDe]
12-16 14:28:09.711 24297 24476 D EM      : <<< [E:36108i M:35017990 (Ack:85930632)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
12-16 14:28:09.711 24297 24476 D IN      : (S) Sending msg 35017990 on secure session with LSID: 25824
12-16 14:28:09.711 24297 24297 I MatterCommissioner: Retrieved PAI chain. [CONTEXT service_id=336 ]
12-16 14:28:09.712 24297 24476 D EM      : Flushed pending ack for MessageCounter:85930632 on exchange 36108i
12-16 14:28:09.712 24297 24297 D DMG     : ICR moving to [AddingComm]
12-16 14:28:09.712 24297 24297 D DMG     : ICR moving to [AddedComma]
12-16 14:28:09.712 24297 24297 D EM      : <<< [E:36109i M:35017991] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
12-16 14:28:09.712 24297 24297 D IN      : (S) Sending msg 35017991 on secure session with LSID: 25824
12-16 14:28:09.713 24297 24297 D DMG     : ICR moving to [CommandSen]
12-16 14:28:09.716 24297 24476 D EM      : >>> [E:36109i M:85930633 (Ack:35017991)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
12-16 14:28:09.716 24297 24476 D EM      : Found matching exchange: 36109i, Delegate: 0x712a71ef88
12-16 14:28:09.716 24297 24476 D EM      : Rxd Ack; Removing MessageCounter:35017991 from Retrans Table on exchange 36109i
12-16 14:28:09.717 24297 24476 D EM      : >>> [E:36109i M:85930634 (Ack:35017991)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
12-16 14:28:09.717 24297 24476 D EM      : Found matching exchange: 36109i, Delegate: 0x712a71ef88
12-16 14:28:09.717 24297 24476 D EM      : CHIP MessageCounter:35017991 not in RetransTable on exchange 36109i
12-16 14:28:09.717 24297 24476 D DMG     : ICR moving to [ResponseRe]
12-16 14:28:09.717 24297 24476 D DMG     : Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
12-16 14:28:09.718 24297 24476 D DMG     : ICR moving to [AwaitingDe]
12-16 14:28:09.719 24297 24476 D EM      : <<< [E:36109i M:35017992 (Ack:85930634)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
12-16 14:28:09.719 24297 24476 D IN      : (S) Sending msg 35017992 on secure session with LSID: 25824
12-16 14:28:09.719 24297 24476 D EM      : Flushed pending ack for MessageCounter:85930634 on exchange 36109i
12-16 14:28:09.720 24297 24297 I MatterCommissioner: Retrieved attestation response. [CONTEXT service_id=336 ]
12-16 14:28:09.721 24297 24297 I MatterCommissioner: Retrieved attestation challenge. [CONTEXT service_id=336 ]
12-16 14:28:09.721 24297 24297 D DMG     : ICR moving to [AddingComm]
12-16 14:28:09.722 24297 24297 D DMG     : ICR moving to [AddedComma]
12-16 14:28:09.722 24297 24297 D EM      : <<< [E:36110i M:35017993] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
12-16 14:28:09.722 24297 24297 D IN      : (S) Sending msg 35017993 on secure session with LSID: 25824
12-16 14:28:09.722 24297 24297 D DMG     : ICR moving to [CommandSen]
12-16 14:28:09.725 24297 24476 D EM      : >>> [E:36110i M:85930635 (Ack:35017993)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
12-16 14:28:09.725 24297 24476 D EM      : Found matching exchange: 36110i, Delegate: 0x71270d5e88
12-16 14:28:09.725 24297 24476 D EM      : Rxd Ack; Removing MessageCounter:35017993 from Retrans Table on exchange 36110i
12-16 14:28:09.726 24297 24476 D EM      : >>> [E:36110i M:85930636 (Ack:35017993)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
12-16 14:28:09.726 24297 24476 D EM      : Found matching exchange: 36110i, Delegate: 0x71270d5e88
12-16 14:28:09.726 24297 24476 D EM      : CHIP MessageCounter:35017993 not in RetransTable on exchange 36110i
12-16 14:28:09.726 24297 24476 D DMG     : ICR moving to [ResponseRe]
12-16 14:28:09.727 24297 24476 D DMG     : Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
12-16 14:28:09.727 24297 24476 D DMG     : ICR moving to [AwaitingDe]
12-16 14:28:09.728 24297 24476 D EM      : <<< [E:36110i M:35017994 (Ack:85930636)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
12-16 14:28:09.728 24297 24297 I MatterCommissioner: Retrieved CsrResponse. [CONTEXT service_id=336 ]
12-16 14:28:09.728 24297 24476 D IN      : (S) Sending msg 35017994 on secure session with LSID: 25824
12-16 14:28:09.728 24297 24476 D EM      : Flushed pending ack for MessageCounter:85930636 on exchange 36110i
12-16 14:28:10.319  5802  5802 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.measurement.START pkg=com.google.android.gms }
12-16 14:28:10.478 24297 24297 I MatterCommissioner: Disarming failsafe. [CONTEXT service_id=336 ]
12-16 14:28:10.478 24297 24297 D CSM     : FindOrEstablishSession: PeerId = [1:CFD6035521232E34]
12-16 14:28:10.479 24297 24297 D CSM     : FindOrEstablishSession: No existing OperationalSessionSetup instance found
12-16 14:28:10.479 24297 24297 D CTL     : OperationalSessionSetup[1:CFD6035521232E34]: State change 1 --> 2
12-16 14:28:10.480 24297 24297 D DIS     : Resolving 2AAD57707A02D131:CFD6035521232E34 ...
12-16 14:28:10.482 24297 24354 I ServiceResolverAdapter: Resolving address for 2AAD57707A02D131-CFD6035521232E34._matter._tcp [CONTEXT service_id=336 ]
12-16 14:28:10.485 24297 24354 I MatterDnsSdServiceResol: Starting search for ResolveServiceRequest{instanceName='2AAD57707A02D131-CFD6035521232E34', serviceType='_matter._tcp'}, timing out in 5000 ms... [CONTEXT service_id=336 ]
12-16 14:28:10.602 24297 24354 I ManagedMdnsServiceBrows: Starting mDNS search for 2AAD57707A02D131-CFD6035521232E34 Options(passive=true, subtypes=[I2AAD57707A02D131], queryMode=ipv4/ipv6) [CONTEXT service_id=336 ]
12-16 14:28:10.720 24297 24476 D DIS     : Checking node lookup status after 240 ms
12-16 14:28:13.566  5802  5802 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.threadnetwork.service.START dat=chimera-action: cmp=com.google.android.gms/.chimera.GmsApiService }
12-16 14:28:14.097  5802  5802 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.home.service.START dat=chimera-action: cmp=com.google.android.gms/.chimera.GmsApiService }
12-16 14:28:15.169  5802  5802 D BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.chimera.container.moduleinstall.ModuleInstallService.START dat=chimera-action: cmp=com.google.android.gms/.chimera.GmsApiService }
12-16 14:28:15.487 24297 27423 I ManagedMdnsServiceBrows: Stopping mDNS search for 2AAD57707A02D131-CFD6035521232E34 [CONTEXT service_id=336 ]
12-16 14:28:15.490 24297 24354 I ServiceResolverAdapter: Timed out searching for 2AAD57707A02D131-CFD6035521232E34._matter._tcp [CONTEXT service_id=336 ]
12-16 14:28:15.491 24297 24354 I ServiceResolverAdapter: No cached mDNS response found for 2AAD57707A02D131-CFD6035521232E34._matter._tcp [CONTEXT service_id=336 ]
12-16 14:28:18.651   763  5197 D ConnectivityService: requestNetwork for uid/pid:10078/27312 NetworkRequest [ TRACK_DEFAULT id=315, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ]
12-16 14:28:18.653   763   979 I chatty  : uid=1000(system) WifiStateMachin expire 10 lines
12-16 14:28:18.653  1506  1506 D PhoneSwitcherNetworkRequstListener: got request NetworkRequest [ TRACK_DEFAULT id=315, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ] with score 60
12-16 14:28:25.525 24297 24476 D DIS     : Checking node lookup status after 15044 ms
12-16 14:28:25.525 24297 24476 E DIS     : OperationalSessionSetup[1:CFD6035521232E34]: operational discovery failed: third_party/connectedhomeip/next/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
12-16 14:28:25.528 24297 24476 W ChipController: Failed to resolve pointer for device CFD6035521232E34 [CONTEXT service_id=336 ]
12-16 14:28:25.528 24297 24476 W ChipController: chip.devicecontroller.ChipDeviceControllerException: third_party/connectedhomeip/next/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
12-16 14:28:25.533 24297 24297 I MatterCommissioner: Could not disarm failsafe (error=0x2A97F190) [CONTEXT service_id=336 ]
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: Commissioning failed with state Failure obtaining credentials. [CONTEXT service_id=336 ]
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: m.epp: Failed to retrieve commissionee credentials.
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.erj.e(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):6)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.erc.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):0)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.nkd.f(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):4)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.nrb.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):7)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at android.os.Handler.handleCallback(Handler.java:790)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at android.os.Handler.dispatchMessage(Handler.java:99)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at android.os.Looper.loop(Looper.java:164)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at android.app.ActivityThread.main(ActivityThread.java:6494)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at java.lang.reflect.Method.invoke(Native Method)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: Caused by: m.feb: RPC ProvisionCertificateForCommissionee returned code CANCELLED; Sherlog for ProvisionCertificateForCommissionee is needed to diagnose.
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.fef.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):28)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.nkd.f(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):4)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.nrb.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):8)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.dtt.c(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):6)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.dtt.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):7)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at abrk.run(:com.google.android.gms@224814019@22.48.14 (040400-493411920):0)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at java.lang.Thread.run(Thread.java:764)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: Caused by: m.mqz: CANCELLED: The operation was cancelled.
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.dse.c(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):95)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.fdb.a(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):59)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	at m.fef.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):11)
12-16 14:28:25.535 24297 24297 E SetupDeviceViewModel: 	... 8 more
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: Showing error status. [CONTEXT service_id=336 ]
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: m.fnx: Failed to retrieve commissionee credentials.
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.fuy.a(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):12)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nxr.a(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):0)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nxq.a(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):7)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.ehi.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):86)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nkd.f(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):4)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nrb.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):7)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at android.os.Handler.handleCallback(Handler.java:790)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at android.os.Handler.dispatchMessage(Handler.java:99)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at android.os.Looper.loop(Looper.java:164)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at android.app.ActivityThread.main(ActivityThread.java:6494)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at java.lang.reflect.Method.invoke(Native Method)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: Caused by: m.epp: Failed to retrieve commissionee credentials.
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.erj.e(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):6)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.erc.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):0)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	... 9 more
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: Caused by: m.feb: RPC ProvisionCertificateForCommissionee returned code CANCELLED; Sherlog for ProvisionCertificateForCommissionee is needed to diagnose.
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.fef.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):28)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nkd.f(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):4)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.nrb.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):8)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.dtt.c(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):6)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.dtt.run(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):7)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at abrk.run(:com.google.android.gms@224814019@22.48.14 (040400-493411920):0)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at java.lang.Thread.run(Thread.java:764)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: Caused by: m.mqz: CANCELLED: The operation was cancelled.
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.dse.c(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):95)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.fdb.a(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):59)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	at m.fef.b(:com.google.android.gms.optional_home@224814031@22.48.14 (020400-0):11)
12-16 14:28:25.538 24297 24297 E SetupDeviceChimeraActiv: 	... 8 more

When I compare this to my custom controller it will just go straight to adding the fabrics certificates after receving the DAC, PAI.

# receive this command from my custom controller before successfully confirm pairing
CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command

But the commissioning using the Google Play Service will just stop with the error on the phone before reaching that point on the device. And timeout and abort the pairing at some point.

@lpfsue
Copy link
Author

lpfsue commented Dec 16, 2022

Something what I want to note: When I look at this I have the feeling that the setup does a lookup for the device in the network, however my understanding is that this appears only after the device was on-boarded (and has received its credentials and certificates).

@lpfsue
Copy link
Author

lpfsue commented Dec 16, 2022

I also confirmed that pairing with the latest Matter virtual device also does fail with the same issue.

Home App: 2.62.1.15
Play Service: 22.48.14 (040400-493411920)

(All this still worked a few days ago.)

@pierredelisle
Copy link
Contributor

A few things to help diagnose this issue:

  • Could you confirm the connectedhomeip commit (SHA) used when you build your device firmware?
  • Which version of the sample app (GHSAFM) are you using?
  • If you could provide the full logs from your phone (see below) along with the device logs, that would be useful.

Full logs on device:
$ adb logcat -c
$ adb logcat > logs.txt

I've seen something similar in the past. This was caused with mismatched signing certs between the device and the client app. See project-chip/connectedhomeip@faad9e1.

@lpfsue
Copy link
Author

lpfsue commented Dec 19, 2022

Hi @pierredelisle

I installed latest version of GHSAFM and re-created my Home and I found the following:

1. I can pair a new Matter device with the GHSAFM app, but previously this on-boarded it also on the Google Fabric (for Google Home). Now it seems that's not the case anymore. In any case, I then go to the device to "Share" it with the Google Home app, and while on-boarding on the Google Home app, the error posted above can be seen.

Full logcat: https://gist.githubusercontent.com/lpfsue/a89c6c22e39780240a1c7756a3a91f5c/raw/f8cccad1b74c8849c61a0db62c7e50f309e0e082/logs_ghsafm_pair_share_android.logs

Again when it fails during pairing after starting the sharing:

12-19 11:30:12.629 24483 24483 E SetupDeviceViewModel: Commissioning failed with state Failure obtaining credentials. [CONTEXT service_id=336 ]
12-19 11:30:12.629 24483 24483 E SetupDeviceViewModel: m.epp: Failed to retrieve commissionee credentials.

Full device logs: https://gist.githubusercontent.com/lpfsue/a89c6c22e39780240a1c7756a3a91f5c/raw/f8cccad1b74c8849c61a0db62c7e50f309e0e082/logs_ghsafm_pair_share_virtual_device.log

2. When I just try to pair the device with the Google Home app, I see the same error at the same stage.

Full logcat: https://gist.githubusercontent.com/lpfsue/a89c6c22e39780240a1c7756a3a91f5c/raw/f8cccad1b74c8849c61a0db62c7e50f309e0e082/logs_gh_pair_android.log

12-19 11:33:07.655 24483 24483 I MatterCommissioner: Could not disarm failsafe (error=0x67915190) [CONTEXT service_id=336 ]
12-19 11:33:07.656 24483 24483 E SetupDeviceViewModel: Commissioning failed with state Failure obtaining credentials. [CONTEXT service_id=336 ]

Full device logs: https://gist.githubusercontent.com/lpfsue/a89c6c22e39780240a1c7756a3a91f5c/raw/f8cccad1b74c8849c61a0db62c7e50f309e0e082/logs_gh_pair_virtual_device.log

App Versions

GHSAFM: v1.2.2
GH: 2.62.1.15
Play Service: 22.48.14
Virtual Device: latest (us-docker.pkg.dev/nest-matter/docker-repo/virtual-device-image@sha256:f867d2b714721cc9b8b4b2d3fdeb8937ee06aade68f0c9b7e1d502a47041c4c0)

Additional Notes: I tried this with two separate setups (with different Google accounts and phones with the same result). This worked with the pre-v1.0 release, then until last week even with the latest v1.0 release but now it's broken. I also checked for the initial report, before I went back to the virtual device, I build the demo with the latest v1.0 commit https://github.com/project-chip/connectedhomeip/tree/v1.0-branch (f6d47664f174adb08df3b7694029c6cd897ebc8c)

@cw-20021349
Copy link

@pierredelisle
Hi
Like lpfsue, I cannot pair with the thread module after the google nest hub 2th device matter 1.0 update.

Screenshot_20221220-155440

Attach log.
PussADB_20221221_103000_mainsys.log

@SebSUE
Copy link

SebSUE commented Dec 22, 2022

Same for me! Getting exactly the same error (also in the adb logcat) when trying to on-board a HUE bridge!

@yurenlee
Copy link

Opps, the same issue after Google Home updated.

@cw-20021349
Copy link

Are you checking with Google on this issue?

@pierredelisle
Copy link
Contributor

All, sorry for the delay. I'll be looking into this today and report back.

@pierredelisle
Copy link
Contributor

@lpfsue

  1. I can pair a new Matter device with the GHSAFM app, but previously this on-boarded it also on the Google Fabric (for Google Home). Now it seems that's not the case anymore.

Correct, this has changed. The device is first commissioned to the local Android fabric, and then control is passed back to GHSAFM to commission into its own fabric.


Now regarding the error:
For the account you use on the Google Home App, do you have associated projects in the Google Home developer console?
There appears to be an issue with attestation failures if that account has multiple projects.

To verify independently that device sharing works fine, I'd suggest testing multi-admin with GHSAFM-TC (target commissioner version of GHSAFM) instead of GHA.

@cw-20021349
Copy link

@pierredelisle

Following your advice, I created and tested only one developer console project in my test account.

But pairing still fails.

Below is the issue path, log and video.

After Google Nest hub 2th generation new firmware release on 12/13, Nethub 2th firmware was updated.
(https://support.google.com/googlenest/answer/7365257?hl=en#zippy=%2Ccurrent-preview-program-firmware-version)

And I checked the release notes on 12/15 and configured the environment for the Matter 1.0 test.
(https://developers.home.google.com/matter/release-notes)

But it doesn't pair with the thread module. My thread module is a Light bulb sample model.
Prior to the Matter 1.0 update, it paired normally.

Issue step

1-1 Thread module Power on (nordic nrf52840 <- Supports Matter 1.0 (use to sdk 2.2.0)
1-2 Enter Google Home (Nest hub 2th registered)
1-3 add and manage
1-4 Set up devcie
1-5 New device
1-6 found matter device
1-7 Scan Matter QR code
1-8 Connecting device to google home..
1-9 pairing failed

The above issue is 100% reproducible.

My Developer Console
https://drive.google.com/file/d/1njXeuUD9bBvl7k8SI6NhQSHJsPNH9H4z/view?usp=sharing

reproduce video
https://drive.google.com/file/d/1TRbETcwY6YJobEYTo2NUoVxXFOSL9_ca/view?usp=sharing

Google Nest hub 2th fw version
https://drive.google.com/file/d/1YNPXQSOzReG6HJFs2ZRZV0O943MyQVhk/view?usp=sharing

issue log
https://drive.google.com/file/d/1sX0YCvFKEOkW_n-Tl7-wImFNqq0gTxwF/view?usp=share_link

Please advise on this matter.

@cw-20021349
Copy link

@pierredelisle

hi..
Due to this problem, our Matter device development has stopped.

I tried removing all the projects from the developer console and recreating just one project and it still doesn't pair.

Prior to the Matter 1.0 update, it paired without problems. Please provide an exact solution for this problem

@pierredelisle
Copy link
Contributor

@cw-20021349

Looking at the video provided, it appears that you are using the Google Home Application to commission.
As I mentioned in a previous post, there appears to be an issue with attestation and the Google team is still working on that issue.

But with respect to this project (GHSAFM), are you able to reproduce with the sample app?
Also, to have a common baseline, I personally test with an M5Stack.

@jahubba
Copy link

jahubba commented Jan 4, 2023

I'm also having the same issue as others. I am unable to pair in Google Home successfully. I only have one project within the home developer console. I have other projects in GCP, but I'm assuming that wouldn't be the issue.

I tested GHSAFM and multi-master with GHSAFM-TC, and that flow worked successfully. I tried multi-master provisioning in GHSAFM and sharing with GHA, but that failed, similar to pairing directly in GHA.

@pierredelisle
Copy link
Contributor

The issues reported here are not directly related to the sample app, so I suggest to do the follow-up in the Google Nest Community > Smart Home Developer Forum.

For example, this issue appears to be the same as the one reported here:
https://www.googlenestcommunity.com/t5/Smart-Home-Developer-Forum/Any-success-stories-of-pairing-after-the-Matt-1-0-update/td-p/327889

@jahubba
Copy link

jahubba commented Jan 4, 2023

@cw-20021349 I was finally able to pair with Google Home. You may want to try again now.

@cw-20021349
Copy link

@jahubba
How did you succeed? Which thread module did you test with?

@jahubba
Copy link

jahubba commented Jan 5, 2023

I wasn't pairing with thread, just wifi. I am using an esp32s3 board with a lighting-app example. I had been getting the same error during pairing, but it started working today. My Google home pairing looks a bit different, too, it has a light bulb during matter pairing now.

@cw-20021349
Copy link

@jahubba
Are you testing on a pixel phone? There was an Android OS update today, do you see any impact?

@jahubba
Copy link

jahubba commented Jan 5, 2023

yes, I am on a pixel phone, (6) and the developer option is on. I did not see an OS upgrade. I'm not sure if my apps upgraded, but below are my versions:

GHA 2.62.80.2
Play store: 33.6.13-21

@cw-20021349
Copy link

I also use pixel 6 and have the same app version as you
However, I use the threads module and it still doesn't get commissioned. ㅠ_ㅠ

Google's Matter 1.0 update is so confusing.

@aBozowski
Copy link
Collaborator

@cw-20021349 sorry to hear that you're still encountering issues!

Are you still seeing the following in your phone's logcat output?

Commissioning failed with state Failure obtaining credentials. 
...
Caused by: m.ezi: RPC ProvisionCertificateForCommissionee returned code INVALID_ARGUMENT

If so, could you please share details of how you are managing certificates for your build?

As mentioned by Pierre above, the developer forums would be the best place to discuss this issue further as the scope of this issue is not specific to the Sample App.

The issue of commissioning failure due to accounts in multiple projects mentioned here should be resolved at this time. For anyone that was able to commission simply by changing to an account that uses only one project, changing back to the original account should now be working.

@cw-20021349
Copy link

@aBozowski
Commissioning was successful last Friday. thank you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants