My app has been working fine until just recently, now it can not add Matter devices over Thread (Wifi commissioning still works). I didn't change anything on my side, so not sure if an update maybe changed things?
In any case, reading through my logs (and i have the matter/thread debug profiles installed). it seems like the device is added to the thread network fine, and it looks to me like the phone is successfully commissioning the device to the Apple setup fabric, but then it seems to choke on this line and i don't think the device is actually added to the keychain/matter db, so it fails later on .
error 12:18:03.369036-0700 homed [2610726604/1195614123(679130348)] failed to find metric hmmtrAccessoryMetricNameCommissioningAccessory to complete
I can confirm the device does join my thread border router as its pingable, and it does not seem to be in setup mode anymore (light stops flashing), so i assume it thinks its commissioned.
The device i'm pairing is a Onvis (matter certified) outlet to an espressif build of a OTBR. My phone is running 18.4.1 if that matters (no pun intended) . I have also cleared out existing Matter pairings from the phone, as well ensured the device was factory reset before every try.
Here is a snippet of the log towards the end where is looks like pairing works, but then errors out. I would post more but my post has a 7k character limit.
default 12:18:02.836555-0700 homed Success status report received. Session was established
default 12:18:02.836734-0700 homed SecureSession[0x9bb100f00, LSID:64711]: State change 'kEstablishing' --> 'kActive'
default 12:18:02.837438-0700 homed Successfully finished commissioning step 'kFindOperationalForStayActive'
default 12:18:02.837467-0700 homed Commissioning stage next step: 'kFindOperationalForStayActive' -> 'ICDSendStayActive'
default 12:18:02.837500-0700 homed Performing next commissioning step 'ICDSendStayActive'
default 12:18:02.837574-0700 homed Skipping kICDSendStayActive
default 12:18:02.837627-0700 homed Successfully finished commissioning step 'ICDSendStayActive'
default 12:18:02.837650-0700 homed Commissioning stage next step: 'ICDSendStayActive' -> 'kFindOperationalForCommissioningComplete'
default 12:18:02.837670-0700 homed Performing next commissioning step 'kFindOperationalForCommissioningComplete'
default 12:18:02.838036-0700 homed Found an existing secure session to [2:000000009B9C86CC]!
default 12:18:02.838149-0700 homed Successfully finished commissioning step 'kFindOperationalForCommissioningComplete'
default 12:18:02.838697-0700 homed Commissioning stage next step: 'kFindOperationalForCommissioningComplete' -> 'SendComplete'
default 12:18:02.838893-0700 homed Performing next commissioning step 'SendComplete'
default 12:18:02.839092-0700 homed <<< [E:35494i S:64711 M:193726318] (S) Msg TX from 0000000086BCA241 to 2:000000009B9C86CC [47A0] [UDP:[fd01:11b8:de1c:1:968a:c465:6fe8:e12a]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
default 12:18:02.839133-0700 homed ??1 [E:35494i S:64711 M:193726318] (S) Msg Retransmission to 2:000000009B9C86CC scheduled for 2910ms from now [State:Active II:800 AI:800 AT:4000]
default 12:18:02.839257-0700 homed <<< [E:35493i S:0 M:19014618 (Ack:7538941)] (U) Msg TX from 3251BD376C43B658 to 0:0000000000000000 [0000] [UDP:[fd01:11b8:de1c:1:968a:c465:6fe8:e12a]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
default 12:18:03.356373-0700 homed >>> [E:35494i S:64711 M:174417481 (Ack:193726318)] (S) Msg RX from 2:000000009B9C86CC [47A0] to 0000000086BCA241 --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
default 12:18:03.356559-0700 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
default 12:18:03.356584-0700 homed Received CommissioningComplete response, errorCode=0
default 12:18:03.356622-0700 homed Successfully finished commissioning step 'SendComplete'
default 12:18:03.356648-0700 homed Commissioning stage next step: 'SendComplete' -> 'Cleanup'
default 12:18:03.356746-0700 homed Performing next commissioning step 'Cleanup'
default 12:18:03.356803-0700 homed Successfully finished commissioning step 'Cleanup'
default 12:18:03.356916-0700 homed Closing all BLE connections
default 12:18:03.357084-0700 homed Auto-closing end point's BLE connection.
default 12:18:03.358146-0700 homed SecureSession[0x9bb1003c0, LSID:64710]: State change 'kActive' --> 'kPendingEviction'
default 12:18:03.358652-0700 homed Commissioning complete for node ID 0x000000009B9C86CC: success
default 12:18:03.358678-0700 homed <MTRDeviceController_Concrete: 0x9b8e33100, uuid: 3F6C2281-D873-4D82-BE3E-722446EA66E7, suspended: NO> DeviceControllerDelegate Commissioning complete. NodeId 0x000000009b9c86cc Status src/controller/CHIPDeviceController.cpp:2932: Success
...
default 12:18:03.367999-0700 homed <MTRDeviceController_Concrete: 0x9b8e33100, uuid: 3F6C2281-D873-4D82-BE3E-722446EA66E7, suspended: NO> 1 delegates called for -[MTRDeviceController controller:commissioningComplete:nodeID:metrics:]
error 12:18:03.369036-0700 homed [2610726604/1195614123(679130348)] failed to find metric hmmtrAccessoryMetricNameCommissioningAccessory to complete
error 12:18:03.426636-0700 HomeUIService Unexpected accessory setup progress CASE Session Sanity Check Passed
default 12:18:03.426850-0700 homed Could not find home with valid fabric ID corresponding to fabric UUID: FB19AA02-5E34-40C5-BB9D-B1B1AF51E08B
...
error 12:18:03.460841-0700 homed [188914BD-5163-425C-9E59-CAE9BFA1A288] Could not find system commissioner pairing for newly staged server with identifier f1:64:16:3f:79:b8 in all pairings: (
..
default 12:18:03.460906-0700 homed Answering incoming message HMASC.m.confirmDeviceCredential (186EE57F-330B-435F-A949-0E4C5D6954AB) from client 'HomeUIService' that expects a response with error Error Domain=HMErrorDomain Code=2 "(null)"
error 12:18:03.461167-0700 HomeUIService [BD890E19] Failed to stage CHIP accessory pairing in steps: Error Domain=HMErrorDomain Code=2 "(null)"
error 12:18:03.462121-0700 HomeUIService -[HSSetupStateMachineCHIPPartnerConfiguration stageCHIPAccessory]_block_invoke Failed to stage CHIP accessory: Error Domain=HMErrorDomain Code=2 "(null)"
default 12:18:03.462172-0700 HomeUIService -[HSSetupStateMachineConfiguration setPairingError:] *** Setting pairingError *** = Error Domain=HMErrorDomain Code=2 "(null)"
