search

stm32-hotspot / stm32wb-matter-device-over-thread

Matter device over thread for STM32WB
Other
26 stars 4 forks source link

Failure Commissioning Example with Apple HomePod Mini #3

Closed chrismerck closed 10 months ago

chrismerck commented 1 year ago

I'm attempting to use the Lighting-App example, commissioned by an Apple HomePod Mini.

I've tried a few times the QR code and discovery ways of setting up. Both go through the Blue then Blue+Green then only Green LED codes on the Nucleo board, but finally fail with "Unable to add Accessory (Accessory is not reachable)" in the Apple Home app.

Is there some reason why the example would not work with off-the-shelf Matter commissioner such as Apple HomePod mini?

Full logs for a discovery-based setup below.

␛[0m[M4 APPLICATION] Matter Over Thread Lighting-App starting...
␛[0m[M4 APPLICATION]  Init matter layer
␛[0m[M4 APPLICATION] Init CHIP stack
CHIP:DL: BLEManagerImpl::Init() complete
␛[0m[M4 APPLICATION] 1- Initialisation of BLE Stack...
␛[0m[M4 APPLICATION] 2- Initialisation of OpenThread Stack. FW info :
␛[0m[M4 APPLICATION] **********************************************************
␛[0m[M4 APPLICATION] WIRELESS COPROCESSOR FW:
␛[0m[M4 APPLICATION] VERSION ID = 1.0.1
␛[0m[M4 APPLICATION] FW Type : Dynamic Concurrent Mode BLE/Thread for Matter
␛[0m[M4 APPLICATION] **********************************************************
␛[0m[M4 APPLICATION] Start init matter
CHIP:-: Current Software Version: 1.0
CHIP:SVR: Server initializing...
CHIP:TS: Last Known Good Time: [unknown]
CHIP:TS: Setting Last Known Good Time to firmware build time 2023-06-19T13:17:17
CHIP:DMG: AccessControl: initializing
CHIP:DMG: Examples::AccessControlDelegate::Init
CHIP:DMG: AccessControl: setting
CHIP:DMG: DefaultAclStorage: initializing
CHIP:DMG: DefaultAclStorage: 0 entries loaded
CHIP:ZCL: Using ZAP configuration...
CHIP:DMG: AccessControlCluster: initializing
CHIP:ZCL: Initiating Admin Commissioning cluster.
CHIP:ZCL: On/Off set value: 1 0
CHIP:ZCL: On/off already set to new value
CHIP:ZCL: Cluster LevelControl: attribute CurrentLevel set to hu
CHIP:-: LightMgr:LEVEL: lev:64->1
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: Failed to finalize service update: 1c
CHIP:DIS: Delaying proxy of operational discovery: missing delegate
CHIP:IN: CASE Server enabling CASE session setups
CHIP:SVR: Server Listening...
CHIP:DL: Device Configuration:
CHIP:DL:   Serial Number: (not set)
CHIP:DL:   Vendor Id: 65521 (0xFFF1)
CHIP:DL:   Product Id: 32772 (0x8004)
CHIP:DL:   Hardware Version: 0
CHIP:DL:   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
CHIP:DL:   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 2560 (0xA00)
CHIP:DL: Invalid manufacturing date: DL
CHIP:DL:   Manufacturing Date: (not set)
CHIP:DL:   Device Type: 257 (0x101)
CHIP:SVR: SetupQRCode: [MT:4CT9142C00C60648G00]
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:4CT9142C00C60648G00
CHIP:SVR: Manual pairing code: [23331712339]
CHIP:DIS: Updating services using commissioning mode 1
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32772 discriminator=2560/10 cm=1
CHIP:DIS: Failed to advertise commissionable node: 3
CHIP:DIS: Failed to finalize service update: 1c
␛[0m[M4 APPLICATION] BLE advertising started. Waiting for Pairing.
␛[0m[M4 APPLICATION] App Task started
CHIP:DL: kAsyncInitCompleted done
CHIP:DL: CHIPoBLE start advertising
CHIP:DL: state return update adv: 0
First index in 0 state

[RTSM] - BLE LL FSM 0 -> 1
[RTSM] - BLE LL FSM 0 -> 1
[RTSM] - BLE APPLICATION STARTS ADV => Radio granted to BLEcheck set discoverable , result: 0
Successfully Start Fast Advertising

[RTSM] - BLE LL FSM 1 -> 2EVT_LE_CONN_COMPLETE for connection handle 0x801
CHIP:DL: Gap connect
CHIP:DL: BLE GATT connection established
CHIP:DL: CHIPoBLE advertising stopped
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 9)
CHIP:BLE: local and remote recv window sizes = 6
CHIP:BLE: selected BTP version 4
CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
Subscribe for c2 notification
-- Matter APPLICATION SERVER : INDICATE ENABLED

CHIP:DL: Write request received for CHIPoBLE TX characteristic CCCD (con 2049, len 0)
CHIP:DL: CHIPoBLE subscribe received
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 84)
CHIP:EM: >>> [E:52745r M:44722254] (U) Msg RX from 0:72E0B50163C8E3A3 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
CHIP:EM: <<< [E:52745r M:5638956] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
CHIP:IN: (U) Sending msg 5638956 to IP address 'BLE'
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 97)
CHIP:EM: >>> [E:52745r M:44722255] (U) Msg RX from 0:72E0B50163C8E3A3 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
CHIP:EM: <<< [E:52745r M:5638957] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
CHIP:IN: (U) Sending msg 5638957 to IP address 'BLE'
CHIP:DL: Long dispatch time: 4945 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 64)
CHIP:EM: >>> [E:52745r M:44722256] (U) Msg RX from 0:72E0B50163C8E3A3 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
CHIP:EM: <<< [E:52745r M:5638958] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
CHIP:IN: (U) Sending msg 5638958 to IP address 'BLE'
CHIP:SC: SecureSession[0x200118b8]: Moving from state 'kEstablishing' --> 'kActive'
CHIP:SVR: Commissioning completed session establishment step
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: Failed to finalize service update: 1c
CHIP:SVR: Device completed Rendezvous process
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:52746r M:262942285] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:52746r M:211543644] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 211543644 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:52747r M:262942286] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:52747r M:211543645] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 211543645 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 57)
CHIP:EM: >>> [E:52748r M:262942287] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:52748r M:211543646] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 211543646 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:EM: >>> [E:52749r M:262942288] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:52749r M:211543647] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 211543647 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 70)
CHIP:EM: >>> [E:52750r M:262942289] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s)
CHIP:EM: <<< [E:52750r M:211543648] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543648 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 75)
CHIP:EM: >>> [E:52751r M:262942290] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: <<< [E:52751r M:211543649] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543649 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 67)
CHIP:EM: >>> [E:52752r M:262942291] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Certificate Chain request received for PAI
CHIP:EM: <<< [E:52752r M:211543650] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543650 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 67)
CHIP:EM: >>> [E:52753r M:262942292] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Certificate Chain request received for DAC
CHIP:EM: <<< [E:52753r M:211543651] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543651 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 99)
CHIP:EM: >>> [E:52754r M:262942293] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Received an AttestationRequest command
CHIP:ZCL: OpCreds: AttestationRequest successful.
CHIP:EM: <<< [E:52754r M:211543652] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543652 on secure session with LSID: 31230
CHIP:DL: Long dispatch time: 1011 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 70)
CHIP:EM: >>> [E:52755r M:262942294] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s)
CHIP:EM: <<< [E:52755r M:211543653] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543653 on secure session with LSID: 31230
                        [RX :x58|B0(0/1)|IT:000|213,0]  34c1 -> ffff    (15)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 99)
CHIP:EM: >>> [E:52756r M:262942295] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Received a CSRRequest command
CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded
CHIP:ZCL: OpCreds: CSRRequest successful.
CHIP:EM: <<< [E:52756r M:211543654] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543654 on secure session with LSID: 31230
CHIP:DL: Long dispatch time: 3011 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 244)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 76)
CHIP:EM: >>> [E:52757r M:262942296] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command
CHIP:ZCL: OpCreds: AddTrustedRootCertificate successful.
CHIP:EM: <<< [E:52757r M:211543655] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543655 on secure session with LSID: 31230
CHIP:DL: Long dispatch time: 2016 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 244)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 115)
CHIP:EM: >>> [E:52758r M:262942297] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Received an AddNOC command
CHIP:FP: Validating NOC chain
CHIP:FP: NOC chain validation successful
CHIP:FP: Added new fabric at index: 0x1
CHIP:FP: Assigned compressed fabric ID: 0x09BE3DC8C4CB6453, node ID: 0x0000000065DA0B1A
CHIP:TS: Last Known Good Time: 2023-06-19T13:17:17
CHIP:TS: New proposed Last Known Good Time: 2023-06-19T18:40:27
CHIP:TS: Updating pending Last Known Good Time to 2023-06-19T18:40:27
CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x5AEACF6F4442697C
CHIP:DIS: Advertise operational node 09BE3DC8C4CB6453-0000000065DA0B1A
CHIP:ZCL: OpCreds: successfully created fabric index 0x1 via AddNOC
CHIP:EM: <<< [E:52758r M:211543656] (S) Msg TX to 1:FFFFFFFB00000000 [6453] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543656 on secure session with LSID: 31230
CHIP:DL: Long dispatch time: 2046 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 143)
CHIP:EM: >>> [E:52759r M:262942298] (S) Msg RX from 1:FFFFFFFB00000000 [6453] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: <<< [E:52759r M:211543657] (S) Msg TX to 1:FFFFFFFB00000000 [6453] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543657 on secure session with LSID: 31230
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 78)
CHIP:EM: >>> [E:52760r M:262942299] (S) Msg RX from 1:FFFFFFFB00000000 [6453] --- Type 0001:08 (IM:InvokeCommandRequest)
                        [TX  x52] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026736 > 6008)        [TX :x52|00811000|..|x52,0000]  680f -> ffff    (25)
                        [RXa:xfc|B0(0/1)|IT:001|213,0]  9001 -> 680f    (25)
                        [TXa x53] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026720 > 8184)        [TXa:x53|OK|x53,0000]   680f -> 9001    (25)
                        [RXa:xfd|B0(0/1)|IT:003|213,0]  9001 -> 680f    (25)
                        [RXa:xfe|B0(0/1)|IT:004|213,0]  9001 -> 680f    (25)
                        [RXa:xff|B0(0/1)|IT:005|213,0]  9001 -> 680f    (25)
CHIP:DL: SRP Client was started, detected server: fdb1:fa4c:e23f:e1dd:0000:00ff:fe00:fc11
CHIP:SVR: Joining Multicast groups
CHIP:EM: <<< [E:52760r M:211543658] (S) Msg TX to 1:FFFFFFFB00000000 [6453] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 211543658 on secure session with LSID: 31230
CHIP:SVR: Joining Multicast groups
CHIP:DIS: Advertise operational node 09BE3DC8C4CB6453-0000000065DA0B1A
CHIP:SVR: Operational advertising enabled
(0009056 > 7960)        [TXa:x54|OK|x54,0000]   680f -> 9001    (25)
                        [RXa:x00|B0(0/1)|IT:007|213,0]  9001 -> 680f    (25)
(0013456 > 9016)        [TXa:x55|OK|x55,0000]   3802 -> 3800    (25)
                        [TXa x56] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026736 > 8952)        [TXa:x56|00010000|..|x56,0000]  3802 -> 3800    (25)
(0022800 > 8728)        [TXa:x57|OK|x57,0000]   3802 -> 3800    (25)
                        [RXa:x01|B0(0/1)|IT:010|213,0]  3800 -> 3802    (25)
CHIP:DIS: Setting operational delegate post init
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: Advertise operational node 09BE3DC8C4CB6453-0000000065DA0B1A
CHIP:DL: advertising srp service: 09BE3DC8C4CB6453-0000000065DA0B1A._matter._tcp
                        [TXa x58] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026736 > 9016)        [TXa:x58|OK|x58,0000]   3802 -> 3800    (25)
(0020208 > 8952)        [TXa:x59|00010000|..|x59,0000]  3802 -> 3800    (25)
(0016912 > 8952)        [TXa:x5a|OK|x5a,0000]   3802 -> 3800    (25)
                        [TXa x5b] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026752 > 8952)        [TXa:x5b|00010000|..|x5b,0000]  3802 -> 3800    (25)
(0024528 > 8760)        [TXa:x5c|OK|x5c,0000]   3802 -> 3800    (25)
                        [RXa:x02|B0(0/1)|IT:014|213,0]  3800 -> 3802    (25)
                        [RXa:x03|B0(0/1)|IT:015|213,0]  3800 -> 3802    (25)
                        [RXa:x04|B0(0/1)|IT:016|213,0]  3800 -> 3802    (25)
                        [RXa:x05|B0(0/1)|IT:017|213,0]  3800 -> 3802    (25)
CHIP:EM: >>> [E:52761r M:44722257] (U) Msg RX from 0:548E8160F8C0086E [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0x20013078
CHIP:IN: CASE Server disabling CASE session setups
CHIP:EM: <<< [E:52761r M:5638959 (Ack:44722257)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 5638959 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:SC: Received Sigma1 msg
                        [TXa x5d] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026752 > 7640)        [TXa:x5d|CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000065DA0B1A
OK|x5d,0000]    3802 -> 3800    (25)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:EM: <<< [E:52761r M:5638960 (Ack:44722257)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
CHIP:IN: (U) Sending msg 5638960 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:SC: Sent Sigma2 msg
CHIP:DL: Long dispatch time: 2977 ms, for event type 3
(0022560 > 8984)        [TXa:x5e|OK|x5e,0000]   3802 -> 3800    (25)
(0015744 > 8952)        [TXa:x5f|00010000|..|x5f,0000]  3802 -> 3800    (25)
(0013072 > 8952)        [TXa:x60|OK|x60,0000]   3802 -> 3800    (25)
                        [TXa x61] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026736 > 8952)        [TXa:x61|00010000|..|x61,0000]  3802 -> 3800    (25)
(0022800 > 8952)        [TXa:x62|OK|x62,0000]   3802 -> 3800    (25)
(0013456 > 7896)        [TXa:x63|00010000|..|x63,0000]  3802 -> 3800    (25)
                        [RX :x63|B0(0/1)|IT:022|213,0]  0100 -> 3802    (25)
                        [RXa:x06|B0(0/1)|IT:023|213,0]  3800 -> 3802    (25)
CHIP:EM: >>> [E:52761r M:44722258 (Ack:5638960)] (U) Msg RX from 0:548E8160F8C0086E [0000] --- Type 0000:40 (SecureChannel:StatusReport)
CHIP:SC: Received error (protocol code 2) during pairing process: 54
CHIP:IN: CASE Session establishment failed: 54
CHIP:EM: <<< [E:52761r M:5638961 (Ack:44722258)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 5638961 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:IN: CASE Server enabling CASE session setups
(0025952 > 7640)        [TXa:x64|OK|x64,0000]   3802 -> 3800    (25)
                        [RXa:x07|B0(0/1)|IT:025|213,0]  3800 -> 3802    (25)
                        [RXa:x08|B0(0/1)|IT:026|213,0]  3800 -> 3802    (25)
                        [RXa:x09|B0(0/1)|IT:027|213,0]  3800 -> 3802    (25)
CHIP:EM: >>> [E:52762r M:44722259] (U) Msg RX from 0:8C45BBBCE23ADD54 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0x20013078
CHIP:IN: CASE Server disabling CASE session setups
CHIP:EM: <<< [E:52762r M:5638962 (Ack:44722259)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 5638962 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:SC: Received Sigma1 msg
(0019008 > 7640)        [TXa:x65|OKCHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000065DA0B1A
|x65,0000]      3802 -> 3800    (25)
CHIP:EM: <<< [E:52762r M:5638963 (Ack:44722259)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
CHIP:IN: (U) Sending msg 5638963 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:SC: Sent Sigma2 msg
CHIP:DL: Long dispatch time: 2980 ms, for event type 3
                        [TXa x66] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026752 > 8984)        [TXa:x66|OK|x66,0000]   3802 -> 3800    (25)
(0018336 > 8952)        [TXa:x67|00010000|..|x67,0000]  3802 -> 3800    (25)
(0014720 > 8952)        [TXa:x68|OK|x68,0000]   3802 -> 3800    (25)
                        [TXa x69] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0026928 > 8952)        [TXa:x69|00010000|..|x69,0000]  3802 -> 3800    (25)
(0024448 > 8952)        [TXa:x6a|OK|x6a,0000]   3802 -> 3800    (25)
(0011040 > 7896)        [TXa:x6b|00010000|..|x6b,0000]  3802 -> 3800    (25)
                        [RX :x6b|B0(0/1)|IT:032|213,0]  0100 -> 3802    (25)
                        [RXa:x0a|B0(0/1)|IT:033|213,0]  3800 -> 3802    (25)
CHIP:EM: >>> [E:52762r M:44722260 (Ack:5638963)] (U) Msg RX from 0:8C45BBBCE23ADD54 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
CHIP:SC: Received error (protocol code 2) during pairing process: 54
CHIP:IN: CASE Session establishment failed: 54
CHIP:EM: <<< [E:52762r M:5638964 (Ack:44722260)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 5638964 to IP address 'UDP:[fd54:892b:38eb:45c0:8dd:6524:16f7:4c14%ot]:60544'
CHIP:IN: CASE Server enabling CASE session setups
                        [TXa x6c] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0025744 > 7640)        [TXa:x6c|OK|x6c,0000]   3802 -> 3800    (25)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
                        [RX :x0c|B0(0/1)|IT:035|213,0]  9001 -> ffff    (25)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:FS: Fail-safe timer expired
CHIP:SVR: Failsafe timer expired
CHIP:SC: SecureSession[0x200118b8]: Moving from state 'kActive' --> 'kPendingEviction'
CHIP:SVR: Commissioning failed (attempt 1): 32
CHIP:BLE: Releasing end point's BLE connection back to application.
CHIP:DL: Closing BLE GATT connection con 45324
CHIP:DIS: Updating services using commissioning mode 1
CHIP:DIS: Advertise operational node 09BE3DC8C4CB6453-0000000065DA0B1A
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32772 discriminator=2560/10 cm=1
CHIP:DL: advertising srp service: ABE533CEB8F05FA2._matterc._udp
CHIP:ZCL: OpCreds: Got FailSafeTimerExpired
CHIP:ZCL: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
CHIP:FP: Reverting pending fabric data for fabric 0x1
CHIP:FP: Warning: metadata not found during delete of fabric 0x1
CHIP:FP: Fabric (0x1) deleted.
CHIP:ZCL: UserLabel: Last Fabric index 0x1 was removed
CHIP:ZCL: OpCreds: Fabric index 0x1 was removed
CHIP:TS: Pending Last Known Good Time: 2023-06-19T18:40:27
CHIP:TS: Previous Last Known Good Time: 2023-06-19T13:17:17
CHIP:TS: Reverted Last Known Good Time to previous value
CHIP:FP: Warning: metadata not found during delete of fabric 0x1
CHIP:ZCL: OpCreds: failed to delete fabric at index 1: d8
CHIP:NP: Reverting Thread operational dataset
CHIP:FS: Fail-safe cleanly disarmed

[RTSM] - BLE LL FSM 2 -> 0
[RTSM] - BLE LL FSM 2 -> 0
[RTSM] - BLE DISCONNECTION Reason : BLE_REASON_MASTER_CLOSE => Task to switch Radio
[RTSM] - TASK Trigged Switch => Radio granted to 15.4
** DISCONNECTION EVENT WITH CLIENT
CHIP:DL: Gap disconnect
CHIP:DL: CHIPoBLE start advertising
CHIP:DL: state return update adv: 0
First index in 0 state

[RTSM] - BLE LL FSM 0 -> 1
[RTSM] - BLE LL FSM 0 -> 1
[RTSM] - BLE APPLICATION STARTS ADV => Radio granted to BLEcheck set discoverable , result: 0
Successfully Start Fast Advertising
                        [TX  x6d] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0091744 > 6008)        [TX :x6d|00811000|..|x6d,0000]  680f -> ffff    (25)
                        [RXa:x0e|B0(0/1)|IT:036|224,0]  9001 -> 680f    (25)
                        [TXa x6e] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...
(0090752 > 8472)        [TXa:x6e|OK|x6e,0000]   680f -> 9001    (25)
                        [RXa:x0f|B0(0/1)|IT:038|224,0]  9001 -> 680f    (25)
                        [RXa:x10|B0(0/1)|IT:039|224,0]  9001 -> 680f    (25)
                        [RXa:x11|B0(0/1)|IT:040|224,0]  9001 -> 680f    (25)
(0064352 > 9016)        [TXa:x6f|OK|x6f,0000]   3802 -> 3800    (25)
(0056864 > 8952)        [TXa:x70|00010000|..|x70,0000]  3802 -> 3800    (25)
(0052928 > 8952)        [TXa:x71|OK|x71,0000]   3802 -> 3800    (25)
(0042288 > 8952)        [TXa:x72|00010000|..|x72,0000]  3802 -> 3800    (25)
(0038656 > 8952)        [TXa:x73|OK|x73,0000]   3802 -> 3800    (25)
(0028032 > 7864)        [TXa:x74|00010000|..|x74,0000]  3802 -> 3800    (25)
                        [RX :x74|B0(0/1)|IT:044|224,0]  9001 -> 680f    (25)
                        [RXa:x12|B0(0/1)|IT:045|224,0]  3800 -> 3802    (25)
                        [RX :x13|B0(0/1)|IT:046|213,0]  9001 -> ffff    (25)
                        [RX :x14|B0(0/1)|IT:047|213,0]  9001 -> ffff    (25)
                        [RX :x15|B0(0/1)|IT:048|217,0]  9001 -> ffff    (25)

[RTSM] - 0000061e|0|0
STYoannZamaron commented 1 year ago

Hello, are you able to reproduce this error. If yes can you put this define to 1 : CHIP_DETAIL_LOGGING . This define will add more logs to understand where it's failed. We tested our solution with home pod mini 2 and it was working in our side. Your log show that you have an error during the CASE step (this step is used to verify that your controller and your device are in the same fabric). Thanks,