search

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

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

Failed to connect to Google Nest Hub 2nd Generation #4

Closed Gonta01 closed 10 months ago

Gonta01 commented 1 year ago

Product ID (0xFFF1) and Vendor ID (0x8004) were added to Google Developer Console. During Commissioning process Blue led was turned on then turned off. Next green led was turned on. Logs:

[M4 APPLICATION] Matter Over Thread Lighting-App starting...
[M4 APPLICATION]  Init matter layer 
[M4 APPLICATION] Init CHIP stack
CHIP:DL: BLEManagerImpl::Init() complete
[M4 APPLICATION] 1- Initialisation of BLE Stack...
[M4 APPLICATION] 2- Initialisation of OpenThread Stack. FW info :
[M4 APPLICATION] **********************************************************
[M4 APPLICATION] WIRELESS COPROCESSOR FW:
[M4 APPLICATION] VERSION ID = 1.0.1
[M4 APPLICATION] FW Type : Dynamic Concurrent Mode BLE/Thread for Matter 
[M4 APPLICATION] **********************************************************
[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-07-07T13:09:56
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
[M4 APPLICATION] BLE advertising started. Waiting for Pairing.
[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

** CONNECTION UPDATE EVENT WITH CLIENT 
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 128 / tx 128.
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

** CONNECTION UPDATE EVENT WITH CLIENT 
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 73)
CHIP:EM: >>> [E:31485r M:102094459] (U) Msg RX from 0:FC01655813703D15 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
CHIP:EM: <<< [E:31485r M:72792681] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
CHIP:IN: (U) Sending msg 72792681 to IP address 'BLE'
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 97)
CHIP:EM: >>> [E:31485r M:102094460] (U) Msg RX from 0:FC01655813703D15 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
CHIP:EM: <<< [E:31485r M:72792682] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
CHIP:IN: (U) Sending msg 72792682 to IP address 'BLE'
CHIP:DL: Long dispatch time: 4956 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 64)
CHIP:EM: >>> [E:31485r M:102094461] (U) Msg RX from 0:FC01655813703D15 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
CHIP:EM: <<< [E:31485r M:72792683] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
CHIP:IN: (U) Sending msg 72792683 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:31486r M:158885997] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31486r M:240811201] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811201 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31487r M:158885998] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31487r M:240811202] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811202 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31488r M:158885999] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31488r M:240811203] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811203 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31489r M:158886000] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31489r M:240811204] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811204 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31490r M:158886001] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31490r M:240811205] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811205 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31491r M:158886002] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31491r M:240811206] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811206 on secure session with LSID: 23556
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 57)
CHIP:EM: >>> [E:31492r M:158886003] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31492r M:240811207] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811207 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 44)
CHIP:EM: >>> [E:31493r M:158886004] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
CHIP:EM: <<< [E:31493r M:240811208] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
CHIP:IN: (S) Sending msg 240811208 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 70)
CHIP:EM: >>> [E:31493r M:158886005] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:FS: GeneralCommissioning: Received ArmFailSafe (120s)
CHIP:EM: <<< [E:31493r M:240811209] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811209 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31494r M:158886006] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31494r M:240811210] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811210 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 44)
CHIP:EM: >>> [E:31495r M:158886007] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
CHIP:EM: <<< [E:31495r M:240811211] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
CHIP:IN: (S) Sending msg 240811211 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 75)
CHIP:EM: >>> [E:31495r M:158886008] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: <<< [E:31495r M:240811212] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811212 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 67)
CHIP:EM: >>> [E:31496r M:158886009] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Certificate Chain request received for DAC
CHIP:EM: <<< [E:31496r M:240811213] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811213 on secure session with LSID: 23556
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 66)
CHIP:EM: >>> [E:31497r M:158886010] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Certificate Chain request received for PAI
CHIP:EM: <<< [E:31497r M:240811214] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811214 on secure session with LSID: 23556
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 98)
CHIP:EM: >>> [E:31498r M:158886011] (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:31498r M:240811215] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811215 on secure session with LSID: 23556
CHIP:DL: Long dispatch time: 1024 ms, for event type 7
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 101)
CHIP:EM: >>> [E:31499r M:158886012] (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:31499r M:240811216] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811216 on secure session with LSID: 23556
CHIP:DL: Long dispatch time: 2982 ms, for event type 7
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:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 119)
CHIP:EM: >>> [E:31500r M:158886013] (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:31500r M:240811217] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811217 on secure session with LSID: 23556
CHIP:DL: Long dispatch time: 2025 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 88)
CHIP:EM: >>> [E:31501r M:158886014] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:ZCL: OpCreds: Received an AddNOC command
CHIP:FP: Validating NOC chain
            [RX :xbf|B0(0/1)|IT:000|157,0]  530a -> ffff    (15)

CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 3)
CHIP:FP: NOC chain validation successful
CHIP:FP: Added new fabric at index: 0x1
CHIP:FP: Assigned compressed fabric ID: 0x24E0364BBFAD1AE7, node ID: 0x00000000A26FBAD3
CHIP:TS: Last Known Good Time: 2023-07-07T13:09:56
CHIP:TS: New proposed Last Known Good Time: 2023-07-07T15:00:21
CHIP:TS: Updating pending Last Known Good Time to 2023-07-07T15:00:21
CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
CHIP:DIS: Advertise operational node 24E0364BBFAD1AE7-00000000A26FBAD3
CHIP:ZCL: OpCreds: successfully created fabric index 0x1 via AddNOC
CHIP:EM: <<< [E:31501r M:240811218] (S) Msg TX to 1:FFFFFFFB00000000 [1AE7] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811218 on secure session with LSID: 23556
CHIP:DL: Long dispatch time: 4081 ms, for event type 7
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 128)
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 48)
CHIP:EM: >>> [E:31502r M:158886015] (S) Msg RX from 1:FFFFFFFB00000000 [1AE7] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIP:EM: <<< [E:31502r M:240811219] (S) Msg TX to 1:FFFFFFFB00000000 [1AE7] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811219 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 56)
CHIP:EM: >>> [E:31503r M:158886016] (S) Msg RX from 1:FFFFFFFB00000000 [1AE7] --- Type 0001:02 (IM:ReadRequest)
CHIP:EM: <<< [E:31503r M:240811220] (S) Msg TX to 1:FFFFFFFB00000000 [1AE7] --- Type 0001:05 (IM:ReportData)
CHIP:IN: (S) Sending msg 240811220 on secure session with LSID: 23556
CHIP:DL: Write request received for CHIPoBLE Client RX characteristic (con 2049, len 78)
CHIP:EM: >>> [E:31504r M:158886017] (S) Msg RX from 1:FFFFFFFB00000000 [1AE7] --- Type 0001:08 (IM:InvokeCommandRequest)
(0020880 > 6008)    [TX :xa5|00811000|..|xa5,0000]  c772 -> ffff    (17)

            [RXa:xf6|B0(0/1)|IT:001|164,0]  f88d -> c772    (17)

            [RXa:xf6|B1(0/1)|IT:002|178,0]  f88d -> c772    (17)

            [RXa:xc3|B0(0/1)|IT:003|157,0]  2505 -> c772    (17)

            [RXa:xe3|B0(0/1)|IT:004|126,0]  63fc -> c772    (17)

            [RXa:x69|B1(0/1)|IT:005|70,0]   cadd -> c772    (17)

00011400|..|xa5,0015]   c772 -> ffff    (17)

            [TX  xa5] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041760 > 6008)    [TX :xa5|00011000|..|xa5,0000]  c772 -> ffff    (17)

            [RX :xe4|B0(0/1)|IT:006|70,0]   63fc -> cadd    (17)

            [RX :x6a|B0(0/1)|IT:007|122,0]  cadd -> 63fc    (17)

            [RX :x6b|B0(0/1)|IT:008|70,0]   cadd -> ffff    (17)

(0032496 > 8504)    [TXa:xa6|OK|xa6,0000]   c772 -> f88d    (17)

            [RXa:xf7|B0(0/1)|IT:010|178,0]  f88d -> c772    (17)

            [RXa:xf8|B0(0/1)|IT:011|182,0]  f88d -> c772    (17)

CHIP:DL: SRP Client was started, detected server: fdc9:ff9e:800e:0000:49b3:7d91:d0d2:bd55
CHIP:SVR: Joining Multicast groups
CHIP:EM: <<< [E:31504r M:240811221] (S) Msg TX to 1:FFFFFFFB00000000 [1AE7] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIP:IN: (S) Sending msg 240811221 on secure session with LSID: 23556
CHIP:DIS: Advertise operational node 24E0364BBFAD1AE7-00000000A26FBAD3
CHIP:SVR: Operational advertising enabled
            [RX :x6c|B0(0/1)|IT:012|157,0]  cadd -> 2505    (17)

(0010096 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

            [TXa xa7] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 7960)    [TXa:xa7|00111000|..|xa7,0014]  c772 -> f88d    (17)

(0034016 > 7960)    [TXa:xa7|00111000|..|xa7,0014]  c772 -> f88d    (17)

(0025024 > 7960)    [TXa:xa7|00111000|..|xa7,0014]  c772 -> f88d    (17)

(0014672 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

            [TXa xa7] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

(0025024 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

            [TXa xa7] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

(0031536 > 7960)    [TXa:xa7|00000500|..|xa7,0015]  c772 -> f88d    (17)

(0017536 > 7960)    [TXa:xa7|00111000|..|xa7,0014]  c772 -> f88d    (17)

            [TXa xa7] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

(0027856 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

(0016544 > 7960)    [TXa:xa7|00911000|..|xa7,0014]  c772 -> f88d    (17)

            [TXa xa7] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 7960)    [TXa:xa7|OK|xa7,0000]   c772 -> f88d    (17)

            [RXa:xf9|B0(0/1)|IT:014|178,0]  f88d -> c772    (17)

            [RXa:xf9|B0(0/1)|IT:015|178,0]  f88d -> c772    (17)

            [RXa:xf9|B1(0/1)|IT:016|178,0]  f88d -> c772    (17)

            [RX :xf6|B0(0/1)|IT:017|178,0]  f88d -> 6000    (17)

(0033472 > 8952)    [TXa:xa8|00911000|..|xa8,0014]  600c -> 6000    (17)

(0020512 > 8952)    [TXa:xa8|OK|xa8,0000]   600c -> 6000    (17)

(0013184 > 8952)    [TXa:xa9|00000400|..|xa9,0000]  600c -> 6000    (17)

            [TXa xaa] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 8984)    [TXa:xaa|00111000|..|xaa,0014]  600c -> 6000    (17)

(0028080 > 8984)    [TXa:xaa|00111000|..|xaa,0014]  600c -> 6000    (17)

(0016784 > 8984)    [TXa:xaa|00111000|..|xaa,0014]  600c -> 6000    (17)

            [TXa xaa] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0041744 > 8984)    [TXa:xaa|OK|xaa,0000]   600c -> 6000    (17)

[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
            [RX :xc5|B0(0/1)|IT:020|122,0]  2505 -> 63fc    (17)

            [RX :xe5|B0(0/1)|IT:021|157,0]  63fc -> 2505    (17)

            [RX :xfa|B0(0/1)|IT:022|126,0]  f88d -> 63fc    (17)

            [RX :x6d|B0(0/1)|IT:023|126,0]  cadd -> 63fc    (17)

            [RX :xe7|B0(0/1)|IT:024|70,0]   63fc -> cadd    (17)

            [RX :xe7|B0(0/1)|IT:025|70,0]   63fc -> cadd    (17)

CHIP:DL: SRP update error: timed out waiting on server response
            [RX :xf7|B0(0/1)|IT:026|175,0]  63fc -> 6000    (17)

            [RX :xfb|B0(0/1)|IT:027|122,0]  f88d -> 63fc    (17)

            [RX :xe8|B0(0/1)|IT:028|175,0]  63fc -> f88d    (17)

(-000001 > 8952)    [TXa:xab|00911000|..|xab,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xab|OK|xab,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xac|00010000|..|xac,0000]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xad|OK|xad,0000]   600c -> 6000    (17)

            [RXa:xfc|B0(0/1)|IT:031|178,0]  6000 -> 600c    (17)

CHIP:DIS: Setting operational delegate post init
CHIP:DIS: Updating services using commissioning mode 0
CHIP:DIS: Advertise operational node 24E0364BBFAD1AE7-00000000A26FBAD3
CHIP:DL: advertising srp service: 24E0364BBFAD1AE7-00000000A26FBAD3._matter._tcp
(-000001 > 8952)    [TXa:xae|00911000|..|xae,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xae|OK|xae,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xaf|00010000|..|xaf,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb0|OK|xb0,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb1|00010000|..|xb1,0000]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xb2|00111000|..|xb2,0014]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xb2|OK|xb2,0000]   600c -> 6000    (17)

            [RX :xf8|B0(0/1)|IT:035|157,0]  0100 -> 6000    (17)

CHIP:DL: SRP update error: timed out waiting on server response
(-000001 > 8952)    [TXa:xb3|OK|xb3,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb4|00010000|..|xb4,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb5|00111000|..|xb5,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb5|OK|xb5,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb6|00010000|..|xb6,0000]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xb7|00111000|..|xb7,0014]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xb7|OK|xb7,0000]   600c -> 6000    (17)

CHIP:DL: SRP update error: timed out waiting on server response
(-000001 > 8952)    [TXa:xb8|OK|xb8,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xb9|00010000|..|xb9,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xba|OK|xba,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xbb|00010000|..|xbb,0000]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xbc|00111000|..|xbc,0014]  600c -> 6000    (17)

(-000001 > 9016)    [TXa:xbc|OK|xbc,0000]   600c -> 6000    (17)

            [RXa:xfd|B0(0/1)|IT:042|171,0]  6000 -> 600c    (17)

            [RXa:xfd|B1(0/1)|IT:043|178,0]  6000 -> 600c    (17)

            [RX :xfa|B0(0/1)|IT:044|175,0]  0100 -> 6000    (17)

            [RX :xfb|B0(0/1)|IT:045|175,0]  0100 -> 6000    (17)

CHIP:BLE: ack recv timeout, closing ep 0x20014de8
CHIP:BLE: Releasing end point's BLE connection back to application.
CHIP:DL: Closing BLE GATT connection con 45324
            [RX :xfc|B0(0/1)|IT:046|178,0]  0100 -> 6000    (17)

            [RX :xfd|B0(0/1)|IT:047|178,0]  0100 -> 6000    (17)

            [RX :xff|B0(0/1)|IT:048|171,0]  0100 -> 6000    (17)

            [RX :xfe|B0(0/1)|IT:049|171,0]  f88d -> ffff    (17)

            [RX :x00|B0(0/1)|IT:050|168,0]  ae40 -> 6000    (17)

            [RX :xe9|B0(0/1)|IT:051|122,0]  63fc -> ffff    (17)

            [RX :x01|B0(0/1)|IT:052|171,0]  8a68 -> 6000    (17)

            [RX :x02|B0(0/1)|IT:053|171,0]  8a68 -> 6000    (17)

            [RX :x03|B0(0/1)|IT:054|171,0]  8a68 -> 6000    (17)

            [RX :xff|B0(0/1)|IT:055|175,0]  6000 -> ffff    (17)

            [RX :xc8|B0(0/1)|IT:056|157,0]  8000 -> ffff    (17)

            [RX :x00|B0(0/1)|IT:057|175,0]  6000 -> ffff    (17)

            [RX :x6f|B0(0/1)|IT:058|80,0]   1400 -> ffff    (17)

            [RX :xc9|B0(0/1)|IT:059|161,0]  8000 -> ffff    (17)

            [RX :x04|B0(0/1)|IT:060|171,0]  0100 -> 6000    (17)

            [RX :x01|B0(0/1)|IT:061|178,0]  0100 -> 6006    (17)

            [RX :xca|B0(0/1)|IT:062|157,0]  2505 -> ffff    (17)

            [RX :x06|B0(0/1)|IT:063|150,0]  aa22 -> 6000    (17)

            [RX :x08|B0(0/1)|IT:064|171,0]  aa22 -> 6000    (17)

            [RXa:x02|B0(0/1)|IT:065|171,0]  6000 -> 600c    (17)

            [RXa:x03|B0(0/1)|IT:066|171,0]  6000 -> 600c    (17)

            [RXa:x03|B0(0/1)|IT:067|164,0]  6000 -> 600c    (17)

            [RXa:x03|B0(0/1)|IT:068|171,0]  6000 -> 600c    (17)

            [RXa:x04|B0(0/1)|IT:069|171,0]  6000 -> 600c    (17)

CHIP:EM: >>> [E:31505r M:102094462] (U) Msg RX from 0:0AB29642C1749568 [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:31505r M:72792684 (Ack:102094462)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 72792684 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:SC: Received Sigma1 msg
(-000001 > 7640)    [TXa:xbd|CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x00000000A26FBAD3
OK|xbd,0000]    600c -> 6000    (17)

            [RX :x09|B0(0/1)|IT:071|150,0]  0100 -> 6000    (17)

CHIP:EM: <<< [E:31505r M:72792685 (Ack:102094462)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
CHIP:IN: (U) Sending msg 72792685 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:SC: Sent Sigma2 msg
CHIP:DL: Long dispatch time: 3005 ms, for event type 3
(-000001 > 8984)    [TXa:xbe|OK|xbe,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xbf|00010000|..|xbf,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc0|00111000|..|xc0,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc0|OK|xc0,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc1|00010000|..|xc1,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc2|00111000|..|xc2,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc2|OK|xc2,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc3|00010000|..|xc3,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc4|00111000|..|xc4,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc4|OK|xc4,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc5|00010000|..|xc5,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc6|00111000|..|xc6,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc6|00111000|..|xc6,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc6|OK|xc6,0000]   600c -> 6000    (17)

(-000001 > 7256)    [TXa:xc7|00010000|..|xc7,0000]  600c -> 6000    (17)

CHIP:IN: (U) Sending msg 72792685 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
(-000001 > 8984)    [TXa:xc8|00111000|..|xc8,0014]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xc8|00111000|..|xc8,0014]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xc8|OK|xc8,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xc9|00010000|..|xc9,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xca|OK|xca,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xcb|00010000|..|xcb,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xcc|00111000|..|xcc,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xcc|OK|xcc,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xcd|00010000|..|xcd,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xce|OK|xce,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xcf|00010000|..|xcf,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd0|OK|xd0,0000]   600c -> 6000    (17)

(-000001 > 7256)    [TXa:xd1|00010000|..|xd1,0000]  600c -> 6000    (17)

            [RX :xd1|B0(0/1)|IT:082|175,0]  0100 -> 6000    (17)

CHIP:IN: (U) Sending msg 72792685 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
(-000001 > 8984)    [TXa:xd2|00111000|..|xd2,0014]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xd2|00111000|..|xd2,0014]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xd2|00111000|..|xd2,0014]  600c -> 6000    (17)

(-000001 > 8984)    [TXa:xd2|OK|xd2,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd3|00010000|..|xd3,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd4|OK|xd4,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd5|00010000|..|xd5,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd6|00111000|..|xd6,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd6|00111000|..|xd6,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd6|OK|xd6,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd7|00010000|..|xd7,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd8|00111000|..|xd8,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd8|00111000|..|xd8,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd8|OK|xd8,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xd9|00010000|..|xd9,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xda|00111000|..|xda,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xda|OK|xda,0000]   600c -> 6000    (17)

(-000001 > 7256)    [TXa:xdb|00010000|..|xdb,0000]  600c -> 6000    (17)

            [RX :x0a|B0(0/1)|IT:088|175,0]  0100 -> 6000    (17)

CHIP:IN: (U) Sending msg 72792685 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
(-000001 > 8984)    [TXa:xdc|OK|xdc,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xdd|00010000|..|xdd,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xde|00111000|..|xde,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xde|OK|xde,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xdf|00010000|..|xdf,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe0|OK|xe0,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe1|00010000|..|xe1,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe2|OK|xe2,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe3|00010000|..|xe3,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe4|00111000|..|xe4,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe4|OK|xe4,0000]   600c -> 6000    (17)

(-000001 > 7256)    [TXa:xe5|00010000|..|xe5,0000]  600c -> 6000    (17)

            [RX :xe5|B0(0/1)|IT:094|175,0]  0100 -> 6000    (17)

            [RX :x0b|B0(0/1)|IT:095|175,0]  0100 -> 6000    (17)

            [RX :xec|B0(0/1)|IT:096|126,0]  63fc -> ffff    (17)

            [RX :x0c|B0(0/1)|IT:097|182,0]  8a68 -> ffff    (17)

            [RX :x0d|B0(0/1)|IT:098|178,0]  8a68 -> 6000    (17)

            [RX :x71|B0(0/1)|IT:099|84,0]   cadd -> ffff    (17)

CHIP:IN: (U) Sending msg 72792685 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
(-000001 > 8984)    [TXa:xe6|OK|xe6,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe7|00010000|..|xe7,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe8|OK|xe8,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xe9|00010000|..|xe9,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xea|00111000|..|xea,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xea|00111000|..|xea,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xea|OK|xea,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xeb|00010000|..|xeb,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|00111000|..|xec,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|00111000|..|xec,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|00111000|..|xec,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|00111000|..|xec,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|00111000|..|xec,0014]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xec|OK|xec,0000]   600c -> 6000    (17)

(-000001 > 8952)    [TXa:xed|00010000|..|xed,0000]  600c -> 6000    (17)

(-000001 > 8952)    [TXa:xee|OK|xee,0000]   600c -> 6000    (17)

(-000001 > 7256)    [TXa:xef|00010000|..|xef,0000]  600c -> 6000    (17)

            [RX :xef|B0(0/1)|IT:105|171,0]  5621 -> ffff    (17)

            [RX :x05|B0(0/1)|IT:106|171,0]  f88d -> ffff    (17)

            [RX :x10|B0(0/1)|IT:107|171,0]  ae40 -> 6000    (17)

            [RX :x11|B0(0/1)|IT:108|171,0]  ae40 -> 6000    (17)

            [RX :x12|B0(0/1)|IT:109|157,0]  ae40 -> 6000    (17)

            [RX :x13|B0(0/1)|IT:110|185,0]  ae40 -> 6000    (17)

            [RX :xcb|B0(0/1)|IT:111|164,0]  2505 -> ffff    (17)

            [RX :x14|B0(0/1)|IT:112|182,0]  aa22 -> 6000    (17)

            [RX :x16|B0(0/1)|IT:113|192,0]  aa22 -> 6000    (17)

            [RX :x17|B0(0/1)|IT:114|182,0]  aa22 -> 6000    (17)

CHIP:EM: Failed to Send CHIP MessageCounter:72792685 on exchange 31505r sendCount: 4 max retries: 4
            [RX :x18|B0(0/1)|IT:115|164,0]  aa22 -> 6000    (17)

            [RX :x19|B0(0/1)|IT:116|182,0]  aa22 -> 6000    (17)

            [RX :x1a|B0(0/1)|IT:117|185,0]  aa22 -> 6000    (17)

            [RX :x06|B0(0/1)|IT:118|185,0]  f88d -> ffff    (17)

            [RX :x1b|B0(0/1)|IT:119|185,0]  ae40 -> 6000    (17)

            [RX :xed|B0(0/1)|IT:120|129,0]  63fc -> ffff    (17)

            [RX :x1d|B0(0/1)|IT:121|189,0]  8a68 -> 6000    (17)

CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 2
CHIP:IN: CASE Session establishment failed: 32
CHIP:IN: CASE Server enabling CASE session setups
            [RX :x1e|B0(0/1)|IT:122|199,0]  8a68 -> 6000    (17)

            [RX :xee|B0(0/1)|IT:123|56,0]   63fc -> cadd    (17)

            [RX :x73|B0(0/1)|IT:124|126,0]  cadd -> 63fc    (17)

            [RX :x73|B0(0/1)|IT:125|122,0]  cadd -> 63fc    (17)

            [RX :xcc|B0(0/1)|IT:126|52,0]   2505 -> cadd    (17)

            [RX :x74|B0(0/1)|IT:127|157,0]  cadd -> 2505    (17)

            [RX :x74|B0(0/1)|IT:128|157,0]  cadd -> 2505    (17)

            [RX :x1f|B0(0/1)|IT:129|203,0]  cadd -> 6000    (17)

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:DIS: Updating services using commissioning mode 1
CHIP:DIS: Advertise operational node 24E0364BBFAD1AE7-00000000A26FBAD3
CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32772 discriminator=2560/10 cm=1
CHIP:DL: advertising srp service: 336B3408E4146DE2._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-07-07T15:00:21
CHIP:TS: Previous Last Known Good Time: 2023-07-07T13:09:56
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
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 

** STOP 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 
(0065616 > 6008)    [TX :xf0|00811000|..|xf0,0000]  c772 -> ffff    (17)

            [RXa:xcd|B0(0/1)|IT:130|150,0]  2505 -> c772    (17)

            [RXa:x07|B0(0/1)|IT:131|203,0]  f88d -> c772    (17)

            [RXa:xcd|B1(0/1)|IT:132|157,0]  2505 -> c772    (17)

            [RXa:x75|B0(0/1)|IT:133|77,0]   cadd -> c772    (17)

            [RXa:xef|B0(0/1)|IT:134|122,0]  63fc -> c772    (17)

(0087968 > 8792)    [TXa:xf1|OK|xf1,0000]   c772 -> f88d    (17)

            [RXa:x08|B0(0/1)|IT:136|206,0]  f88d -> c772    (17)

            [RXa:x09|B0(0/1)|IT:137|206,0]  f88d -> c772    (17)

(0041456 > 8952)    [TXa:xf2|00911000|..|xf2,0014]  600c -> 6000    (17)

(0033280 > 8952)    [TXa:xf2|OK|xf2,0000]   600c -> 6000    (17)

(0025648 > 8952)    [TXa:xf3|00010000|..|xf3,0000]  600c -> 6000    (17)

(0023424 > 8952)    [TXa:xf4|00111000|..|xf4,0014]  600c -> 6000    (17)

(0011904 > 8952)    [TXa:xf4|OK|xf4,0000]   600c -> 6000    (17)

            [TXa xf5] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0088736 > 8952)    [TXa:xf5|00010000|..|xf5,0000]  600c -> 6000    (17)

(0086512 > 8952)    [TXa:xf6|00111000|..|xf6,0014]  600c -> 6000    (17)

(0072464 > 8952)    [TXa:xf6|00111000|..|xf6,0014]  600c -> 6000    (17)

(0054208 > 8952)    [TXa:xf6|OK|xf6,0000]   600c -> 6000    (17)

(0046256 > 8120)    [TXa:xf7|00010000|..|xf7,0000]  600c -> 6000    (17)

            [RX :xf7|B0(0/1)|IT:141|206,0]  f88d -> c772    (17)

            [RXa:x0a|B0(0/1)|IT:142|206,0]  6000 -> 600c    (17)

            [RX :x20|B0(0/1)|IT:143|203,0]  0100 -> 6000    (17)

            [RX :x21|B0(0/1)|IT:144|192,0]  0100 -> 6000    (17)

            [RX :x22|B0(0/1)|IT:145|182,0]  0100 -> 6000    (17)

            [RX :x23|B0(0/1)|IT:146|199,0]  0100 -> 6000    (17)

            [RX :xf0|B0(0/1)|IT:147|115,0]  63fc -> ffff    (17)

            [RX :xce|B0(0/1)|IT:148|157,0]  2505 -> ffff    (17)

            [RX :x24|B0(0/1)|IT:149|196,0]  aa22 -> 6000    (17)

            [RX :x25|B0(0/1)|IT:150|192,0]  aa22 -> 6000    (17)

            [RX :x0b|B0(0/1)|IT:151|192,0]  f88d -> ffff    (17)

            [RX :x26|B0(0/1)|IT:152|192,0]  ae40 -> 6000    (17)

            [RXa:x0c|B0(0/1)|IT:153|192,0]  6000 -> 600c    (17)

            [RXa:x0d|B0(0/1)|IT:154|192,0]  6000 -> 600c    (17)

            [RXa:x0e|B0(0/1)|IT:155|192,0]  6000 -> 600c    (17)

CHIP:EM: >>> [E:31506r M:102094463] (U) Msg RX from 0:709D0C96DFF34410 [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:31506r M:72792686 (Ack:102094463)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 72792686 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:SC: Received Sigma1 msg
CHIP:SC: CASE failed to match destination ID with local fabrics
CHIP:EM: <<< [E:31506r M:72792687 (Ack:102094463)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
(0015600 > 7640)    [TXa:xf8|CHIP:IN: (U) Sending msg 72792687 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:IN: CASE Session establishment failed: 71
CHIP:IN: CASE Server enabling CASE session setups
CHIP:EM: OnMessageReceived failed, err = 71
CHIP:IN: CASE Server enabling CASE session setups
OK|xf8,0000]    600c -> 6000    (17)

            [TXa xf9] -> #CAF:0 So ST_Dynamic_otPlatRadioTransmit() Pending...

(0086736 > 7896)    [TXa:xf9|00010000|..|xf9,0000]  600c -> 6000    (17)

            [RX :xf9|B0(0/1)|IT:157|192,0]  0100 -> 600c    (17)

            [RXa:x0f|B0(0/1)|IT:158|192,0]  6000 -> 600c    (17)

CHIP:EM: >>> [E:31506r M:102094464 (Ack:72792687)] (U) Msg RX from 0:709D0C96DFF34410 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
            [RX :x27|B0(0/1)|IT:159|192,0]  0100 -> 6000    (17)

            [RX :x10|B0(0/1)|IT:160|192,0]  6000 -> ffff    (17)

            [RX :xf1|B1(0/1)|IT:161|129,0]  c800 -> ffff    (17)

            [RX :x11|B0(0/1)|IT:162|192,0]  6000 -> ffff    (17)

            [RX :xcf|B0(0/1)|IT:163|157,0]  8000 -> ffff    (17)

            [RXa:x12|B0(0/1)|IT:164|192,0]  6000 -> 600c    (17)

            [RX :xd0|B1(0/1)|IT:165|157,0]  8000 -> ffff    (17)

            [RXa:x13|B0(0/1)|IT:166|192,0]  6000 -> 600c    (17)

            [RXa:x13|B0(0/1)|IT:167|199,0]  6000 -> 600c    (17)

            [RXa:x13|B0(0/1)|IT:168|192,0]  6000 -> 600c    (17)

            [RXa:x14|B0(0/1)|IT:169|192,0]  6000 -> 600c    (17)

CHIP:EM: >>> [E:31507r M:102094465] (U) Msg RX from 0:0128CFBC1F76FD3F [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:31507r M:72792688 (Ack:102094465)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
CHIP:IN: (U) Sending msg 72792688 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:SC: Received Sigma1 msg
CHIP:SC: CASE failed to match destination ID with local fabrics
CHIP:EM: <<< [E:31507r M:72792689 (Ack:102094465)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
(0062656 > 7640)    [TXa:xfa|CHIP:IN: (U) Sending msg 72792689 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
CHIP:IN: CASE Session establishment failed: 71
CHIP:IN: CASE Server enabling CASE session setups
CHIP:EM: OnMessageReceived failed, err = 71
CHIP:IN: CASE Server enabling CASE session setups
OK|xfa,0000]    600c -> 6000    (17)

(0032096 > 7896)    [TXa:xfb|00010000|..|xfb,0000]  600c -> 6000    (17)

CHIP:IN: (U) Sending msg 72792689 to IP address 'UDP:[fdae:651e:36d7:3a74:9812:753f:b074:e094%ot]:36487'
(0053792 > 7896)    [TXa:xfc|OK|xfc,0000]   600c -> 6000    (17)

            [RXa:x15|B0(0/1)|IT:172|192,0]  6000 -> 600c    (17)

CHIP:EM: >>> [E:31507r M:102094466 (Ack:72792689)] (U) Msg RX from 0:0128CFBC1F76FD3F [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
            [RX :x28|B0(0/1)|IT:173|192,0]  0100 -> 6000    (17)

[RTSM] - 000002b2|0|0           [RX :x29|B0(0/1)|IT:174|192,0]  0100 -> 6000    (17)

            [RX :x78|B0(0/1)|IT:175|56,0]   cadd -> ffff    (17)

            [RX :x2b|B0(0/1)|IT:176|192,0]  5621 -> 6000    (17)

            [RX :x2c|B0(0/1)|IT:177|189,0]  5621 -> 6000    (17)

            [RX :x2d|B0(0/1)|IT:178|192,0]  5621 -> 6000    (17)

            [RX :x2e|B0(0/1)|IT:179|192,0]  5621 -> 6000    (17)

            [RX :xd1|B0(0/1)|IT:180|161,0]  2505 -> ffff    (17)
STYoannZamaron commented 1 year ago

Hello can you try again with this log at 1 #define CHIP_DETAIL_LOGGING 1 in CHIPProjectConfig.h Thanks Yoann

Gonta01 commented 1 year ago

In one cases device doesn't connect to Google Home. In another it could connect but without any controls available. This time device connected to Google Home but it isn't possible to control it.

define CHIP_DETAIL_LOGGING 1 was set in CHIPProjectConfig.h

Logs: stm32wb_matter_log_2.log

STYoannZamaron commented 1 year ago

Hello, When you are doing the commissioning, the controller is losing the ble link with the end devices before the end of the commissioning. That why you cannot control the end device after because for him you didn t receive the commissioning complete from the controller.

Gonta01 commented 1 year ago

Hello. Could you please explain what logs have given you such information? What are possible reasons of this problem and how to fix them? Also I see in the logs the following message: CHIP:DMG: CHIP_ERROR_PERSISTED_STORAGE_NOT_FOUND Could it be the problem also?

STYoannZamaron commented 1 year ago

you have those log.
[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: BLE GATT connection closed (con 2049)

just before creating the SRP. The best way to solve this issue is to take a ble sniffer and check the trace. To know if it's the google home application that leave the connection or the end device that disconnect for non-reason.

CHIP:DMG: CHIP_ERROR_PERSISTED_STORAGE_NOT_FOUND => No it's good, just mean that you don t have the key in the nvm but it's normal. It's more like a check if not present matter will create it.

Gonta01 commented 1 year ago

While using CHIP-tool the following logs occurred on CHIP-tool side:

[1689086105.840279][9838:9840] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1689086105.840301][9838:9840] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1689086105.840313][9838:9840] CHIP:CTL: Verifying attestation
[1689086105.897140][9838:9840] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 601. Look at AttestationVerificationResult enum to understand the errors
[1689086105.897212][9838:9840] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../.espressif/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
[1689086105.897233][9838:9840] CHIP:CTL: Failed to perform commissioning step 8
[1689086105.897255][9838:9840] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../.espressif/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'

So there is some problem with certificates.

Gonta01 commented 1 year ago

In CHIPProjectConfig.h file there is such lines of code:

/**
 * CHIP_DEVICE_CONFIG_DEVICE_PRODUCT_ID
 *
 * 0x8005: example lighting app
 */
#define CHIP_DEVICE_CONFIG_DEVICE_PRODUCT_ID 0x8004

Does it mean that for Lighting app example I need to change Product Id on 0x8005? But as I see the QR code is for 0x8004 product ID.

STYoannZamaron commented 1 year ago

hello, this software is compatible with matter chip-tool controller V1.0.0 and will not be compatible with other versions of chip-tool. Product_id can stay 0x8004 for a lighting application.

Gonta01 commented 1 year ago

hello, thank you for your answers and explanations. Continue to investigate the problem and I have an assumption. Maybe the cause of the problem is that BLE and Thread for some reason can't work simultaneously on microcontroller? Radio granted to 15.4. 15.4 stands for Thread as I understand.

[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
Gonta01 commented 1 year ago

The strange thing is that in some cases commissioning is successful. But still it isn't possible to control device in app. For example logs: stm32wb_matter_log_5.txt

STYoannZamaron commented 1 year ago

hello can you try with chip-tool : https://github.com/project-chip/connectedhomeip/tree/v1.0-branch with RPi + Border Router. BR

Gonta01 commented 1 year ago

Hello. Successfully commissioned device with the usage of Android chip tool from this repository. Works fine, it is possible to control LED. Another OTBR was used, not the one recommended here. stm32wb_android_chip_tool.log As it can be seen from logs BLE is off after commissioning completed.

In the case of connecting to Google Home BLE is off before commissioning finished. The problem remains. How make software of STM32WB compatible with off-the-shelf Matter commissioner like Google Nest hub?

Gonta01 commented 1 year ago

Are these logs generated by wireless coprocessor?

[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

There isn't any functions that generate such logs in source files. Is this implemented in stm32wb5x_BLE_Thread_ForMatter_fw.bin?

STYoannZamaron commented 1 year ago

hello, yes those logs are generated by the RTSM module. this module provides the switch between the ble ip et thread ip.

Gonta01 commented 1 year ago

Get it. Is it possible to figure out the reason why BLE disconnects before commissioning finished in the case of Nest hub? Or it is hidden in binary files so the reason cannot be figured out from my side?

STYoannZamaron commented 1 year ago

if it s only with google. the best way would be to retrieve the google home log with adb. I think the google home app close the ble link with the end device.