Inconsistent connections with Matter

Hi, we are developing a Matter Window Covering device. Our product is battery operated so we are using Matter over Thread in SSED role. Right now, things seem to be working, but not all the time. I am struggling to understand the root cause because the behaviour is highly inconsistent. 

Here are some behaviours we have observed:

  • In Apple Home, device is "not responding". Sometimes, this is the case immediately after commissioning. Other times, this happens after a few minutes. Sometimes it recovers by itself, sometimes it doesn't. In all cases, we did not move the location of the device with respect to the border router (Apple TV 4K). 
  • In Google Home, commissioning fails 9/10 times. Sometimes it says "cannot reach device" and other times "cannot connect to the network". Attached are a couple of device logs attempting to commission to Google Home.
    ooting Zephyr OS build v3.2.99-ncs1 ***
    I: GPIO Button Initialization Initialization done
    I: Low Power UART Initialization init done
    I: Init CHIP stack
    32muart:~$ I: 251 [DL]BLE address: F9:BA:7F:51:82:1B
    I: SoftDevice Controller build revision:
    I: 6d 90 41 2a 38 e8 ad 17 |m.A*8...
    I: 29 a5 03 38 39 27 d7 85 |)..89'..
    I: 1f 85 d8 e1             |....
    I: 273 [DL]OpenThread SED interval set to 500ms
    I: 283 [DL]OpenThread started: OK
    I: 286 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE
    I: 294 [SVR]Server initializing...
    I: 298 [TS]Last Known Good Time: [unknown]
    I: 302 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13
    I: 314 [DMG]AccessControl: initializing
    I: 318 [DMG]Examples::AccessControlDelegate::Init
    I: 322 [DMG]AccessControl: setting
    I: 325 [DMG]DefaultAclStorage: initializing
    I: 329 [DMG]DefaultAclStorage: 0 entries loaded
    E: 334 [IN]SO_REUSEPORT failed: 109
    I: 353 [ZCL]Using ZAP configuration...
    I: 373 [DMG]AccessControlCluster: initializing
    I: 377 [ZCL]Initiating Admin Commissioning cluster.
    I: 382 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1
    I: 389 [DIS]Updating services using commissioning mode 0
    I: 395 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 404 [DIS]Failed to advertise extended commissionable node: 3
    E: 410 [DIS]Failed to finalize service update: 1c
    I: 414 [DIS]Delaying proxy of operational discovery: missing delegate
    I: 420 [IN]CASE Server enabling CASE session setups
    I: 425 [SVR]Joining Multicast groups
    I: 429 [SVR]Server Listening...
    I: 431 [DL]Device Configuration:
    I: 435 [DL]  Serial Number: 11223344556677889900
    I: 440 [DL]  Vendor Id: 65521 (0xFFF1)
    I: 443 [DL]  Product Id: 32784 (0x8010)
    I: 448 [DL]  Hardware Version: 0
    I: 452 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
    I: 458 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
    I: 465 [DL]  Manufacturing Date: (not set)
    I: 469 [DL]  Device Type: 65535 (0xFFFF)
    I: 475 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
    I: 479 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    I: 485 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
    I: 494 [SVR]Manual pairing code: [34970112332]
    I: 500 [DL]CHIP task running
    I: 502 [DIS]Updating services using commissioning mode 0
    I: 509 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 518 [DIS]Failed to advertise extended commissionable node: 3
    E: 524 [DIS]Failed to finalize service update: 1c
    I:
    
    build time: Dec 18 2022 20:04:16
    
    
    I: Bluetooth initialized
    D: set-value OK. key: bt/name
    D: set-value OK. key: bt/hash
    I: Dendo BLE services initialized
    I:
    doAction
    nRFState = PRE_START
    nRFdoAction = nRF_START
    I: Matter not Commissioned!!!
    I:
    doAction
    nRFState = PRE_START
    nRFdoAction = nRF_IDLE
    I:
    ActionTimeoutLEDStatus
    nRFState = IDLE
    nRFdoAction = nRF_IDLE
    I:
    doAction
    nRFState = PRE_SHUT
    nRFdoAction = nRF_SHUTDOWN
    I:
    doAction
    nRFState = PRE_SHUT
    nRFdoAction = nRF_IDLE
    I:
    ActionTimeoutLEDStatus
    nRFState = SLEEP
    nRFdoAction = nRF_IDLE
    I:
    Unknow Short Press
    nRFState = SLEEP
    nRFdoAction = nRF_IDLE
    I:
    doAction
    nRFState = PRE_START
    nRFdoAction = nRF_START
    I: Matter not Commissioned!!!
    I:
    doAction
    nRFState = MT_COMMIS
    nRFdoAction = MATTER_COMMIS_OPEN
    I: 95796 [DIS]Updating services using commissioning mode 1
    I: 95802 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
    E: 95812 [DIS]Failed to advertise commissionable node: 3
    E: 95817 [DIS]Failed to finalize service update: 1c
    I: 95824 [DL]CHIPoBLE advertising started
    I:
    
    BLE advertising is enabled
    I: 105828 [DL]CHIPoBLE advertising mode changed to slow
    I: Updated MTU: TX: 23 RX: 23 bytes
    I: Connected 65:73:16:34:B9:00 (random)
    I: 123005 [DL]BLE connection established (ConnId: 0x00)
    I: 123010 [DL]Current number of connections: 1/1
    I: 123014 [DL]CHIPoBLE advertising stopped
    I:
    
    BLE advertising is disabled
    I: Updated MTU: TX: 131 RX: 131 bytes
    I: 124030 [BLE]local and remote recv window sizes = 5
    I: 124034 [BLE]selected BTP version 4
    I: 124038 [BLE]using BTP fragment sizes rx 128 / tx 128.
    I: 124045 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
    I:
    kCHIPoBLEConnectionEstablished
    I: 124106 [EM]>>> [E:6280r M:184105635] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    I: 124119 [EM]<<< [E:6280r M:9310781] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 124131 [IN](U) Sending msg 9310781 to IP address 'BLE'
    I: 124466 [EM]>>> [E:6280r M:184105636] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    I: 126489 [EM]<<< [E:6280r M:9310782] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 126500 [IN](U) Sending msg 9310782 to IP address 'BLE'
    E: 126505 [DL]Long dispatch time: 2040 ms, for event type 16388
    I: 126671 [EM]>>> [E:6280r M:184105637] (U) Msg RX from 0:A9B1A46B706DC46B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    I: 126683 [EM]<<< [E:6280r M:9310783] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 126693 [IN](U) Sending msg 9310783 to IP address 'BLE'
    I: 126700 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive'
    I: 126708 [SVR]Commissioning completed session establishment step
    I: 126714 [DIS]Updating services using commissioning mode 0
    I: 126721 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 126731 [DIS]Failed to advertise extended commissionable node: 3
    E: 126736 [DIS]Failed to finalize service update: 1c
    I: 126741 [SVR]Device completed Rendezvous process
    I: 126761 [EM]>>> [E:6281r M:7556274] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 126773 [EM]<<< [E:6281r M:21205970] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 126783 [IN](S) Sending msg 21205970 on secure session with LSID: 55695
    I: 126896 [EM]>>> [E:6282r M:7556275] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 126908 [EM]<<< [E:6282r M:21205971] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 126918 [IN](S) Sending msg 21205971 on secure session with LSID: 55695
    I: 126986 [EM]>>> [E:6283r M:7556276] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 126998 [EM]<<< [E:6283r M:21205972] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 127008 [IN](S) Sending msg 21205972 on secure session with LSID: 55695
    I: 127076 [EM]>>> [E:6284r M:7556277] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 127088 [EM]<<< [E:6284r M:21205973] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 127098 [IN](S) Sending msg 21205973 on secure session with LSID: 55695
    I: 127166 [EM]>>> [E:6285r M:7556278] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 127178 [EM]<<< [E:6285r M:21205974] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 127188 [IN](S) Sending msg 21205974 on secure session with LSID: 55695
    I: 127256 [EM]>>> [E:6286r M:7556279] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 127270 [EM]<<< [E:6286r M:21205975] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 127280 [IN](S) Sending msg 21205975 on secure session with LSID: 55695
    I: 127751 [EM]>>> [E:6287r M:7556280] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 127763 [EM]<<< [E:6287r M:21205976] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 127773 [IN](S) Sending msg 21205976 on secure session with LSID: 55695
    I: 128831 [EM]>>> [E:6288r M:7556281] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 128842 [EM]<<< [E:6288r M:21205977] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 128852 [IN](S) Sending msg 21205977 on secure session with LSID: 55695
    I: 128922 [EM]>>> [E:6288r M:7556282] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 128933 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
    I: 128940 [EM]<<< [E:6288r M:21205978] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 128950 [IN](S) Sending msg 21205978 on secure session with LSID: 55695
    I: 129011 [EM]>>> [E:6289r M:7556283] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 129023 [EM]<<< [E:6289r M:21205979] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 129033 [IN](S) Sending msg 21205979 on secure session with LSID: 55695
    I: 129101 [EM]>>> [E:6290r M:7556284] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 129112 [EM]<<< [E:6290r M:21205980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 129122 [IN](S) Sending msg 21205980 on secure session with LSID: 55695
    I: 129192 [EM]>>> [E:6290r M:7556285] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 129212 [EM]<<< [E:6290r M:21205981] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 129223 [IN](S) Sending msg 21205981 on secure session with LSID: 55695
    I: 129282 [EM]>>> [E:6291r M:7556286] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 129293 [ZCL]OpCreds: Certificate Chain request received for DAC
    I: 129302 [EM]<<< [E:6291r M:21205982] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 129313 [IN](S) Sending msg 21205982 on secure session with LSID: 55695
    I: 129732 [EM]>>> [E:6292r M:7556287] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 129743 [ZCL]OpCreds: Certificate Chain request received for PAI
    I: 129752 [EM]<<< [E:6292r M:21205983] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 129763 [IN](S) Sending msg 21205983 on secure session with LSID: 55695
    I: 130182 [EM]>>> [E:6293r M:7556288] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 130193 [ZCL]OpCreds: Received an AttestationRequest command
    I: 130230 [ZCL]OpCreds: AttestationRequest successful.
    I: 130239 [EM]<<< [E:6293r M:21205984] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 130249 [IN](S) Sending msg 21205984 on secure session with LSID: 55695
    I: 130767 [EM]>>> [E:6294r M:7556289] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 130778 [ZCL]OpCreds: Received a CSRRequest command
    I: 130981 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 131018 [ZCL]OpCreds: CSRRequest successful.
    I: 131024 [EM]<<< [E:6294r M:21205985] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 131035 [IN](S) Sending msg 21205985 on secure session with LSID: 55695
    E: 131042 [DL]Long dispatch time: 276 ms, for event type 16388
    I: 133558 [EM]>>> [E:6295r M:7556290] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 133569 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 133633 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    I: 133640 [EM]<<< [E:6295r M:21205986] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 133651 [IN](S) Sending msg 21205986 on secure session with LSID: 55695
    E: 133658 [DL]Long dispatch time: 102 ms, for event type 16388
    I: 134190 [EM]>>> [E:6296r M:7556291] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 134201 [ZCL]OpCreds: Received an AddNOC command
    I: 134210 [FP]Validating NOC chain
    I: 134329 [FP]NOC chain validation successful
    I: 134333 [FP]Added new fabric at index: 0x1
    I: 134337 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x000000007A661996
    I: 134345 [TS]Last Known Good Time: 2022-12-18T20:04:13
    I: 134350 [TS]New proposed Last Known Good Time: 2023-01-17T10:52:05
    I: 134356 [TS]Updating pending Last Known Good Time to 2023-01-17T10:52:05
    I: 134386 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
    I: 134395 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996
    I: 134402 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    I: 134409 [EM]<<< [E:6296r M:21205987] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 134420 [IN](S) Sending msg 21205987 on secure session with LSID: 55695
    E: 134427 [DL]Long dispatch time: 241 ms, for event type 16388
    I: 134592 [EM]>>> [E:6297r M:7556292] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 134610 [EM]<<< [E:6297r M:21205988] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 134621 [IN](S) Sending msg 21205988 on secure session with LSID: 55695
    I: 134682 [EM]>>> [E:6298r M:7556293] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest)
    I: 134694 [EM]<<< [E:6298r M:21205989] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData)
    I: 134703 [IN](S) Sending msg 21205989 on secure session with LSID: 55695
    I: 134772 [EM]>>> [E:6299r M:7556294] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 135824 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be
    I: 135839 [EM]<<< [E:6299r M:21205990] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 135850 [IN](S) Sending msg 21205990 on secure session with LSID: 55695
    I: 135857 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996
    I: 135863 [SVR]Operational advertising enabled
    I: 136605 [DIS]Setting operational delegate post init
    I: 136616 [SWU]Stopping the watchdog timer
    I: 136620 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 136626 [DIS]Updating services using commissioning mode 0
    I: 136632 [DIS]Advertise operational node 86ACCD207670D93A-000000007A661996
    I: 136639 [DL]advertising srp service: 86ACCD207670D93A-000000007A661996._matter._tcp
    I: 136647 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    I: 136657 [DL]advertising srp service: 5A393C33336681F1._matterc._udp
    I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19)
    I: 144811 [DL]BLE GAP connection terminated (reason 0x13)
    I: 144817 [DL]Current number of connections: 0/1
    I:
    kCHIPoBLEConnectionClosed
    E: 146047 [DL]BLEManagerImpl::SendIndication() failed: 2f
    I: 146052 [BLE]Releasing end point's BLE connection back to application.
    I: 146058 [DL]Closing BLE GATT connection (ConnId 00)
    I: STATE CHANGING HERE
    I:
    doAction
    nRFState = IDLE
    nRFdoAction = nRF_IDLE
    I:
    doAction
    nRFState = PRE_SHUT
    nRFdoAction = nRF_SHUTDOWN
    E: 176994 [FP]Reverting pending fabric data for fabric 0x1
    E: 177001 [FP]Warning: metadata not found during delete of fabric 0x1
    I: 177019 [FP]Fabric (0x1) deleted.
    I: 177022 [ZCL]OpCreds: Fabric index 0x1 was removed
    I: 177053 [TS]Pending Last Known Good Time: 2023-01-17T10:52:05
    I: 177060 [TS]Previous Last Known Good Time: 2022-12-18T20:04:13
    I: 177066 [TS]Reverted Last Known Good Time to previous value
    I: 177072 [DL]Performing factory reset
    I: 177098 [DL]Erasing Thread persistent info...
    I: nRF5 802154 radio initialized
    E: JEDEC id [00 00 00] expect [c2 28 17]
    D: Recovering last ate from sector 2
    I: 4 Sectors of 4096 bytes
    I: alloc wra: 2, a70
    I: data wra: 2, 3e4
    D: Initialized
    
    
    ooting Zephyr OS build v3.2.99-ncs1 ***
    I: GPIO Button Initialization Initialization done
    I: Low Power UART Initialization init done
    I: Init CHIP stack
    32muart:~$ I: 250 [DL]BLE address: DC:4B:4D:80:0C:BF
    I: SoftDevice Controller build revision:
    I: 6d 90 41 2a 38 e8 ad 17 |m.A*8...
    I: 29 a5 03 38 39 27 d7 85 |)..89'..
    I: 1f 85 d8 e1             |....
    I: 272 [DL]OpenThread SED interval set to 500ms
    I: 282 [DL]OpenThread started: OK
    I: 285 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE
    I: 293 [SVR]Server initializing...
    I: 297 [TS]Last Known Good Time: [unknown]
    I: 301 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13
    I: 313 [DMG]AccessControl: initializing
    I: 317 [DMG]Examples::AccessControlDelegate::Init
    I: 321 [DMG]AccessControl: setting
    I: 324 [DMG]DefaultAclStorage: initializing
    I: 328 [DMG]DefaultAclStorage: 0 entries loaded
    E: 333 [IN]SO_REUSEPORT failed: 109
    I: 351 [ZCL]Using ZAP configuration...
    I: 371 [DMG]AccessControlCluster: initializing
    I: 376 [ZCL]Initiating Admin Commissioning cluster.
    I: 381 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1
    I: 387 [DIS]Updating services using commissioning mode 0
    I: 394 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 403 [DIS]Failed to advertise extended commissionable node: 3
    E: 408 [DIS]Failed to finalize service update: 1c
    I: 413 [DIS]Delaying proxy of operational discovery: missing delegate
    I: 419 [IN]CASE Server enabling CASE session setups
    I: 424 [SVR]Joining Multicast groups
    I: 427 [SVR]Server Listening...
    I: 430 [DL]Device Configuration:
    I: 434 [DL]  Serial Number: 11223344556677889900
    I: 438 [DL]  Vendor Id: 65521 (0xFFF1)
    I: 442 [DL]  Product Id: 32784 (0x8010)
    I: 446 [DL]  Hardware Version: 0
    I: 450 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
    I: 456 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
    I: 464 [DL]  Manufacturing Date: (not set)
    I: 468 [DL]  Device Type: 65535 (0xFFFF)
    I: 473 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
    I: 478 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    I: 484 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
    I: 493 [SVR]Manual pairing code: [34970112332]
    I: 498 [DL]CHIP task running
    I: 501 [DIS]Updating services using commissioning mode 0
    I: 507 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 516 [DIS]Failed to advertise extended commissionable node: 3
    E: 522 [DIS]Failed to finalize service update: 1c
    I:
    
    build time: Dec 18 2022 20:04:16
    
    
    I: Bluetooth initialized
    D: set-value OK. key: bt/name
    D: set-value OK. key: bt/hash
    I: Dendo BLE services initialized
    I:
    doAction
    nRFState = PRE_START
    nRFdoAction = nRF_START
    I: Matter not Commissioned!!!
    I:
    doAction
    nRFState = MT_COMMIS
    nRFdoAction = MATTER_COMMIS_OPEN
    I: 4046 [DIS]Updating services using commissioning mode 1
    I: 4052 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
    E: 4061 [DIS]Failed to advertise commissionable node: 3
    E: 4066 [DIS]Failed to finalize service update: 1c
    I: 4073 [DL]CHIPoBLE advertising started
    I:
    
    BLE advertising is enabled
    I: 14078 [DL]CHIPoBLE advertising mode changed to slow
    I: Updated MTU: TX: 23 RX: 23 bytes
    I: Connected 65:73:16:34:B9:00 (random)
    I: 45857 [DL]BLE connection established (ConnId: 0x00)
    I: 45862 [DL]Current number of connections: 1/1
    I: 45866 [DL]CHIPoBLE advertising stopped
    I:
    
    BLE advertising is disabled
    I: Updated MTU: TX: 131 RX: 131 bytes
    I: 46931 [BLE]local and remote recv window sizes = 5
    I: 46935 [BLE]selected BTP version 4
    I: 46939 [BLE]using BTP fragment sizes rx 128 / tx 128.
    I: 46976 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
    I:
    kCHIPoBLEConnectionEstablished
    I: 47202 [EM]>>> [E:6326r M:184105664] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    I: 47214 [EM]<<< [E:6326r M:6302907] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 47226 [IN](U) Sending msg 6302907 to IP address 'BLE'
    I: 47427 [EM]>>> [E:6326r M:184105665] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    I: 49437 [EM]<<< [E:6326r M:6302908] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 49447 [IN](U) Sending msg 6302908 to IP address 'BLE'
    E: 49453 [DL]Long dispatch time: 2027 ms, for event type 16388
    I: 49722 [EM]>>> [E:6326r M:184105666] (U) Msg RX from 0:B9D985E3A7024C23 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    I: 49734 [EM]<<< [E:6326r M:6302909] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 49744 [IN](U) Sending msg 6302909 to IP address 'BLE'
    I: 49751 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive'
    I: 49758 [SVR]Commissioning completed session establishment step
    I: 49764 [DIS]Updating services using commissioning mode 0
    I: 49772 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 49781 [DIS]Failed to advertise extended commissionable node: 3
    E: 49787 [DIS]Failed to finalize service update: 1c
    I: 49791 [SVR]Device completed Rendezvous process
    I: 49812 [EM]>>> [E:6327r M:236808937] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 49824 [EM]<<< [E:6327r M:192161873] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 49834 [IN](S) Sending msg 192161873 on secure session with LSID: 6040
    I: 49902 [EM]>>> [E:6328r M:236808938] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 49914 [EM]<<< [E:6328r M:192161874] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 49924 [IN](S) Sending msg 192161874 on secure session with LSID: 6040
    I: 49992 [EM]>>> [E:6329r M:236808939] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 50004 [EM]<<< [E:6329r M:192161875] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 50014 [IN](S) Sending msg 192161875 on secure session with LSID: 6040
    I: 50082 [EM]>>> [E:6330r M:236808940] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 50094 [EM]<<< [E:6330r M:192161876] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 50104 [IN](S) Sending msg 192161876 on secure session with LSID: 6040
    I: 50172 [EM]>>> [E:6331r M:236808941] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 50184 [EM]<<< [E:6331r M:192161877] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 50194 [IN](S) Sending msg 192161877 on secure session with LSID: 6040
    I: 50262 [EM]>>> [E:6332r M:236808942] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 50276 [EM]<<< [E:6332r M:192161878] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 50286 [IN](S) Sending msg 192161878 on secure session with LSID: 6040
    I: 50712 [EM]>>> [E:6333r M:236808943] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 50724 [EM]<<< [E:6333r M:192161879] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 50734 [IN](S) Sending msg 192161879 on secure session with LSID: 6040
    I: 51972 [EM]>>> [E:6334r M:236808944] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 51983 [EM]<<< [E:6334r M:192161880] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 51993 [IN](S) Sending msg 192161880 on secure session with LSID: 6040
    I: 52063 [EM]>>> [E:6334r M:236808945] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 52074 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
    I: 52081 [EM]<<< [E:6334r M:192161881] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 52092 [IN](S) Sending msg 192161881 on secure session with LSID: 6040
    I: 52153 [EM]>>> [E:6335r M:236808946] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 52164 [EM]<<< [E:6335r M:192161882] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 52174 [IN](S) Sending msg 192161882 on secure session with LSID: 6040
    I: 52242 [EM]>>> [E:6336r M:236808947] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 52253 [EM]<<< [E:6336r M:192161883] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 52264 [IN](S) Sending msg 192161883 on secure session with LSID: 6040
    I: 52333 [EM]>>> [E:6336r M:236808948] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 52353 [EM]<<< [E:6336r M:192161884] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 52364 [IN](S) Sending msg 192161884 on secure session with LSID: 6040
    I: 52423 [EM]>>> [E:6337r M:236808949] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 52434 [ZCL]OpCreds: Certificate Chain request received for DAC
    I: 52443 [EM]<<< [E:6337r M:192161885] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 52454 [IN](S) Sending msg 192161885 on secure session with LSID: 6040
    I: 52873 [EM]>>> [E:6338r M:236808950] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 52884 [ZCL]OpCreds: Certificate Chain request received for PAI
    I: 52893 [EM]<<< [E:6338r M:192161886] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 52904 [IN](S) Sending msg 192161886 on secure session with LSID: 6040
    I: 53323 [EM]>>> [E:6339r M:236808951] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 53334 [ZCL]OpCreds: Received an AttestationRequest command
    I: 53371 [ZCL]OpCreds: AttestationRequest successful.
    I: 53379 [EM]<<< [E:6339r M:192161887] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 53390 [IN](S) Sending msg 192161887 on secure session with LSID: 6040
    I: 53908 [EM]>>> [E:6340r M:236808952] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 53919 [ZCL]OpCreds: Received a CSRRequest command
    I: 54120 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 54156 [ZCL]OpCreds: CSRRequest successful.
    I: 54163 [EM]<<< [E:6340r M:192161888] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 54174 [IN](S) Sending msg 192161888 on secure session with LSID: 6040
    E: 54181 [DL]Long dispatch time: 274 ms, for event type 16388
    I: 56249 [EM]>>> [E:6341r M:236808953] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 56261 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 56324 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    I: 56331 [EM]<<< [E:6341r M:192161889] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 56342 [IN](S) Sending msg 192161889 on secure session with LSID: 6040
    E: 56349 [DL]Long dispatch time: 102 ms, for event type 16388
    I: 56881 [EM]>>> [E:6342r M:236808954] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 56892 [ZCL]OpCreds: Received an AddNOC command
    I: 56901 [FP]Validating NOC chain
    I: 57019 [FP]NOC chain validation successful
    I: 57023 [FP]Added new fabric at index: 0x1
    I: 57027 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x000000002EFEEE7A
    I: 57035 [TS]Last Known Good Time: 2022-12-18T20:04:13
    I: 57040 [TS]New proposed Last Known Good Time: 2023-01-17T10:53:47
    I: 57046 [TS]Updating pending Last Known Good Time to 2023-01-17T10:53:47
    I: 57076 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
    I: 57085 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A
    I: 57092 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    I: 57099 [EM]<<< [E:6342r M:192161890] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 57110 [IN](S) Sending msg 192161890 on secure session with LSID: 6040
    E: 57117 [DL]Long dispatch time: 240 ms, for event type 16388
    I: 57283 [EM]>>> [E:6343r M:236808955] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 57301 [EM]<<< [E:6343r M:192161891] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 57312 [IN](S) Sending msg 192161891 on secure session with LSID: 6040
    I: 57373 [EM]>>> [E:6344r M:236808956] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest)
    I: 57385 [EM]<<< [E:6344r M:192161892] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData)
    I: 57395 [IN](S) Sending msg 192161892 on secure session with LSID: 6040
    I: 57463 [EM]>>> [E:6345r M:236808957] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 58834 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be
    I: 58849 [EM]<<< [E:6345r M:192161893] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 58860 [IN](S) Sending msg 192161893 on secure session with LSID: 6040
    I: 58866 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A
    I: 58873 [SVR]Operational advertising enabled
    I: 59818 [DIS]Setting operational delegate post init
    I: 59828 [SWU]Stopping the watchdog timer
    I: 59832 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 59838 [DIS]Updating services using commissioning mode 0
    I: 59844 [DIS]Advertise operational node 86ACCD207670D93A-000000002EFEEE7A
    I: 59851 [DL]advertising srp service: 86ACCD207670D93A-000000002EFEEE7A._matter._tcp
    I: 59860 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    I: 59869 [DL]advertising srp service: 44C0CF57F9788AC6._matterc._udp
    I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19)
    I: 80283 [DL]BLE GAP connection terminated (reason 0x13)
    I: 80289 [DL]Current number of connections: 0/1
    I:
    kCHIPoBLEConnectionClosed
    I: STATE CHANGING HERE
    I:
    doAction
    nRFState = IDLE
    nRFdoAction = nRF_IDLE
    uart:~$ *** Booting Zephyr OS build v3.2.99-ncs1 ***
    I: GPIO Button Initialization Initialization done
    I: Low Power UART Initialization init done
    I: Init CHIP stack
    D: Moving 32768, len 2
    D: Moving 32776, len 7
    D: Moving 49160, len 12
    D: Moving 32773, len 7
    D: Adding gc done ate at fd0
    D: Erasing flash at fc000, len 4096
    I: 478 [DL]BLE address: D5:7D:87:14:C7:1E
    I: SoftDevice Controller build revision:
    I: 6d 90 41 2a 38 e8 ad 17 |m.A*8...
    I: 29 a5 03 38 39 27 d7 85 |)..89'..
    I: 1f 85 d8 e1             |....
    I: 500 [DL]OpenThread SED interval set to 500ms
    I: 510 [DL]OpenThread started: OK
    I: 513 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE
    I: 520 [SVR]Server initializing...
    I: 524 [TS]Last Known Good Time: [unknown]
    I: 528 [TS]Setting Last Known Good Time to firmware build time 2022-12-18T20:04:13
    I: 541 [DMG]AccessControl: initializing
    I: 544 [DMG]Examples::AccessControlDelegate::Init
    I: 549 [DMG]AccessControl: setting
    I: 552 [DMG]DefaultAclStorage: initializing
    I: 556 [DMG]DefaultAclStorage: 0 entries loaded
    E: 560 [IN]SO_REUSEPORT failed: 109
    I: 579 [ZCL]Using ZAP configuration...
    I: 597 [DMG]AccessControlCluster: initializing
    I: 601 [ZCL]Initiating Admin Commissioning cluster.
    I: 606 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1
    I: 613 [DIS]Updating services using commissioning mode 0
    I: 619 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 628 [DIS]Failed to advertise extended commissionable node: 3
    E: 634 [DIS]Failed to finalize service update: 1c
    I: 638 [DIS]Delaying proxy of operational discovery: missing delegate
    I: 644 [IN]CASE Server enabling CASE session setups
    I: 649 [SVR]Joining Multicast groups
    I: 653 [SVR]Server Listening...
    I: 656 [DL]Device Configuration:
    I: 659 [DL]  Serial Number: 11223344556677889900
    I: 664 [DL]  Vendor Id: 65521 (0xFFF1)
    I: 667 [DL]  Product Id: 32784 (0x8010)
    I: 672 [DL]  Hardware Version: 0
    I: 675 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
    I: 682 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
    I: 689 [DL]  Manufacturing Date: (not set)
    I: 693 [DL]  Device Type: 65535 (0xFFFF)
    I: 698 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
    I: 703 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    I: 709 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
    I: 718 [SVR]Manual pairing code: [34970112332]
    I: 723 [DL]CHIP task running
    I: 726 [DIS]Updating services using commissioning mode 0
    I: 732 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 741 [DIS]Failed to advertise extended commissionable node: 3
    E: 747 [DIS]Failed to finalize service update: 1c
    I:
    
    build time: Dec 18 2022 20:04:16
    
    
    I: Bluetooth initialized
    D: set-value OK. key: bt/name
    D: set-value OK. key: bt/hash
    I: Dendo BLE services initialized
    I:
    doAction
    nRFState = PRE_START
    nRFdoAction = nRF_START
    I: Matter not Commissioned!!!
    I:
    doAction
    nRFState = MT_COMMIS
    nRFdoAction = MATTER_COMMIS_OPEN
    I: 3588 [DIS]Updating services using commissioning mode 1
    I: 3594 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
    E: 3603 [DIS]Failed to advertise commissionable node: 3
    E: 3608 [DIS]Failed to finalize service update: 1c
    I: 3615 [DL]CHIPoBLE advertising started
    I:
    
    BLE advertising is enabled
    I: 13619 [DL]CHIPoBLE advertising mode changed to slow
    I: Updated MTU: TX: 23 RX: 23 bytes
    I: Connected 65:73:16:34:B9:00 (random)
    I: 34234 [DL]BLE connection established (ConnId: 0x00)
    I: 34239 [DL]Current number of connections: 1/1
    I: 34243 [DL]CHIPoBLE advertising stopped
    I:
    
    BLE advertising is disabled
    I: Updated MTU: TX: 131 RX: 131 bytes
    I: 35430 [BLE]local and remote recv window sizes = 5
    I: 35435 [BLE]selected BTP version 4
    I: 35438 [BLE]using BTP fragment sizes rx 128 / tx 128.
    I: 35453 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
    I:
    kCHIPoBLEConnectionEstablished
    I: 35507 [EM]>>> [E:6356r M:184105677] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    I: 35520 [EM]<<< [E:6356r M:213354608] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 35531 [IN](U) Sending msg 213354608 to IP address 'BLE'
    I: 35731 [EM]>>> [E:6356r M:184105678] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    I: 37744 [EM]<<< [E:6356r M:213354609] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 37755 [IN](U) Sending msg 213354609 to IP address 'BLE'
    E: 37761 [DL]Long dispatch time: 2030 ms, for event type 16388
    I: 38026 [EM]>>> [E:6356r M:184105679] (U) Msg RX from 0:061356A67F050A56 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    I: 38038 [EM]<<< [E:6356r M:213354610] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 38049 [IN](U) Sending msg 213354610 to IP address 'BLE'
    I: 38055 [SC]SecureSession[0x20003ee8]: Moving from state 'kEstablishing' --> 'kActive'
    I: 38063 [SVR]Commissioning completed session establishment step
    I: 38069 [DIS]Updating services using commissioning mode 0
    I: 38076 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    E: 38086 [DIS]Failed to advertise extended commissionable node: 3
    E: 38092 [DIS]Failed to finalize service update: 1c
    I: 38096 [SVR]Device completed Rendezvous process
    I: 38117 [EM]>>> [E:6357r M:163203305] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38129 [EM]<<< [E:6357r M:225510285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38139 [IN](S) Sending msg 225510285 on secure session with LSID: 58234
    I: 38207 [EM]>>> [E:6358r M:163203306] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38219 [EM]<<< [E:6358r M:225510286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38229 [IN](S) Sending msg 225510286 on secure session with LSID: 58234
    I: 38297 [EM]>>> [E:6359r M:163203307] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38309 [EM]<<< [E:6359r M:225510287] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38319 [IN](S) Sending msg 225510287 on secure session with LSID: 58234
    I: 38387 [EM]>>> [E:6360r M:163203308] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38399 [EM]<<< [E:6360r M:225510288] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38409 [IN](S) Sending msg 225510288 on secure session with LSID: 58234
    I: 38477 [EM]>>> [E:6361r M:163203309] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38489 [EM]<<< [E:6361r M:225510289] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38499 [IN](S) Sending msg 225510289 on secure session with LSID: 58234
    I: 38567 [EM]>>> [E:6362r M:163203310] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 38581 [EM]<<< [E:6362r M:225510290] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 38590 [IN](S) Sending msg 225510290 on secure session with LSID: 58234
    I: 39062 [EM]>>> [E:6363r M:163203311] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 39073 [EM]<<< [E:6363r M:225510291] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 39083 [IN](S) Sending msg 225510291 on secure session with LSID: 58234
    I: 40231 [EM]>>> [E:6364r M:163203312] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 40242 [EM]<<< [E:6364r M:225510292] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 40253 [IN](S) Sending msg 225510292 on secure session with LSID: 58234
    I: 40322 [EM]>>> [E:6364r M:163203313] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 40333 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
    I: 40340 [EM]<<< [E:6364r M:225510293] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 40351 [IN](S) Sending msg 225510293 on secure session with LSID: 58234
    I: 40412 [EM]>>> [E:6365r M:163203314] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    I: 40424 [EM]<<< [E:6365r M:225510294] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 40434 [IN](S) Sending msg 225510294 on secure session with LSID: 58234
    I: 40502 [EM]>>> [E:6366r M:163203315] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
    I: 40513 [EM]<<< [E:6366r M:225510295] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
    I: 40523 [IN](S) Sending msg 225510295 on secure session with LSID: 58234
    I: 40592 [EM]>>> [E:6366r M:163203316] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 40612 [EM]<<< [E:6366r M:225510296] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 40623 [IN](S) Sending msg 225510296 on secure session with LSID: 58234
    I: 40682 [EM]>>> [E:6367r M:163203317] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 40693 [ZCL]OpCreds: Certificate Chain request received for DAC
    I: 40703 [EM]<<< [E:6367r M:225510297] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 40713 [IN](S) Sending msg 225510297 on secure session with LSID: 58234
    I: 41132 [EM]>>> [E:6368r M:163203318] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 41143 [ZCL]OpCreds: Certificate Chain request received for PAI
    I: 41152 [EM]<<< [E:6368r M:225510298] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 41163 [IN](S) Sending msg 225510298 on secure session with LSID: 58234
    I: 41582 [EM]>>> [E:6369r M:163203319] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 41594 [ZCL]OpCreds: Received an AttestationRequest command
    I: 41630 [ZCL]OpCreds: AttestationRequest successful.
    I: 41639 [EM]<<< [E:6369r M:225510299] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 41650 [IN](S) Sending msg 225510299 on secure session with LSID: 58234
    I: 42167 [EM]>>> [E:6370r M:163203320] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 42179 [ZCL]OpCreds: Received a CSRRequest command
    I: 42381 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 42417 [ZCL]OpCreds: CSRRequest successful.
    I: 42424 [EM]<<< [E:6370r M:225510300] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 42435 [IN](S) Sending msg 225510300 on secure session with LSID: 58234
    E: 42442 [DL]Long dispatch time: 276 ms, for event type 16388
    I: 44554 [EM]>>> [E:6371r M:163203321] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 44565 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 44629 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    I: 44635 [EM]<<< [E:6371r M:225510301] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 44646 [IN](S) Sending msg 225510301 on secure session with LSID: 58234
    E: 44653 [DL]Long dispatch time: 102 ms, for event type 16388
    I: 45185 [EM]>>> [E:6372r M:163203322] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 45196 [ZCL]OpCreds: Received an AddNOC command
    I: 45205 [FP]Validating NOC chain
    I: 45323 [FP]NOC chain validation successful
    I: 45327 [FP]Added new fabric at index: 0x1
    I: 45331 [FP]Assigned compressed fabric ID: 0x86ACCD207670D93A, node ID: 0x00000000271F26F2
    I: 45340 [TS]Last Known Good Time: 2022-12-18T20:04:13
    I: 45345 [TS]New proposed Last Known Good Time: 2023-01-17T10:58:53
    I: 45351 [TS]Updating pending Last Known Good Time to 2023-01-17T10:58:53
    I: 45380 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
    I: 45389 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2
    I: 45396 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    I: 45403 [EM]<<< [E:6372r M:225510302] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 45414 [IN](S) Sending msg 225510302 on secure session with LSID: 58234
    E: 45421 [DL]Long dispatch time: 240 ms, for event type 16388
    I: 45588 [EM]>>> [E:6373r M:163203323] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 45605 [EM]<<< [E:6373r M:225510303] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 45616 [IN](S) Sending msg 225510303 on secure session with LSID: 58234
    I: 45677 [EM]>>> [E:6374r M:163203324] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:02 (IM:ReadRequest)
    I: 45689 [EM]<<< [E:6374r M:225510304] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:05 (IM:ReportData)
    I: 45699 [IN](S) Sending msg 225510304 on secure session with LSID: 58234
    I: 45768 [EM]>>> [E:6375r M:163203325] (S) Msg RX from 1:FFFFFFFB00000000 [D93A] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 47418 [DL]SRP Client was started, detected server: fdda:dc55:58c8:0000:335d:5e1c:f16e:f2be
    I: 47433 [EM]<<< [E:6375r M:225510305] (S) Msg TX to 1:FFFFFFFB00000000 [D93A] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 47444 [IN](S) Sending msg 225510305 on secure session with LSID: 58234
    I: 47451 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2
    I: 47457 [SVR]Operational advertising enabled
    I: 47902 [DIS]Setting operational delegate post init
    I: 47911 [SWU]Stopping the watchdog timer
    I: 47915 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 47921 [DIS]Updating services using commissioning mode 0
    I: 47927 [DIS]Advertise operational node 86ACCD207670D93A-00000000271F26F2
    I: 47934 [DL]advertising srp service: 86ACCD207670D93A-00000000271F26F2._matter._tcp
    I: 47942 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
    I: 47952 [DL]advertising srp service: E013E1AB4B9A6BD5._matterc._udp
    I: Disconnected: 65:73:16:34:B9:00 (random) (reason 19)
    I: 56302 [DL]BLE GAP connection terminated (reason 0x13)
    I: 56307 [DL]Current number of connections: 0/1
    I:
    kCHIPoBLEConnectionClosed
    E: 57626 [DL]BLEManagerImpl::SendIndication() failed: 2f
    I: 57631 [BLE]Releasing end point's BLE connection back to application.
    I: 57637 [DL]Closing BLE GATT connection (ConnId 00)
    I: STATE CHANGING HERE
    I:
    doAction
    nRFState = IDLE
    nRFdoAction = nRF_IDLE
  • When Google Home commissioning is successful, it will eventually become disconnected after an indeterminate period of time.
  • Samsung SmartThings commissioning seems to work more consistently than the other two. However, it too loses the connection after some time.

I have tested both our custom firmware on custom board, as well as the Nordic Window Covering sample on the nRF52840 DK. The behaviour is the same in both cases. I should also note that we do not yet have membership with CSA and therefore are using the testing Vendor ID. I'm not sure if this might have anything to do with the issues we are experiencing?

Any help greatly appreciated! Really struggling here.

Parents Reply Children
Related