Inconsistent connections with Matter

[whyeye]

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.
  Fullscreen Unable to connect to Google Home.txt Download

  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

  Fullscreen GH Commissioning cannot reach device.txt Download

  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.

[whyeye]

Thanks, Marte. I have a gut feeling that the Google Home issues might be related to the BLE implementation on specific Android hardware/software combinations. A colleague of mine seems to have much better luck on a One Plus phone, whereas I am running a Google Pixel 4 on Android 13.

[Marte Myrvold]

Hi,

I believe you might be correct. I have asked the development team if they are aware of there being an issue with certain Android devices.

Best regards,

Marte

[Marte Myrvold]

Hi,

The developers suspect it might be an Android software issue rather than specific phones. I tested with a phone with the same Android version as you, 13. As far as I know, OnePlus does not support Android 13 yet, so that might explain why your colleague was able to get it to work. I will do some more testing and see if I can verify this.

In the meantime, the developers asked if you can try to reinstall the Google Home app and make sure that the cache is clear, as well as factory reset the Google Hub.

Best regards,

Marte

[YunjooKim]

Hi Marte and whyeye,

I'm having a similar issue too.

Commissioning fails at Google and Apple.

At Samsung, commissioning is successful. (QR Code and Pin Code)

Tested with NCS v2.2.0 / light_bulb.

If you succeed in commissioning at Google and Apple in the future, could you share your test environment?

It's very useful to me.

Additionally, I attach the log of my testing.

01_Samsung_QR_Code.txt

Fullscreen 02_Apple_QR_Code.txt Download

                                                                                                               
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, f00
I: data wra: 0, d0


ooting Zephyr OS build v3.2.99-ncs1 ***
I: Init CHIP stack
32muart:~$ : 222 [DL]BLE address: CD:DB:8D:84:48:6A
mI: 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: 246 [DL]OpenThread started: OK
I: 249 [DL]Setting OpenThread device type to ROUTER
I: 254 [SVR]Server initializing...
D: 257 [FP]Initializing FabricTable from persistent storage
I: 262 [TS]Last Known Good Time: 2023-01-25T11:24:03
I: 268 [DMG]AccessControl: initializing
I: 271 [DMG]Examples::AccessControlDelegate::Init
I: 276 [DMG]AccessControl: setting
I: 279 [DMG]DefaultAclStorage: initializing
I: 283 [DMG]DefaultAclStorage: 0 entries loaded
D: 287 [IN]UDP::Init bind&listen port=5540
E: 291 [IN]SO_REUSEPORT failed: 109
D: 294 [IN]UDP::Init bound to port=5540
D: 298 [IN]BLEBase::Init - setting/overriding transport
D: 302 [IN]TransportMgr initialized
D: 309 [DL]Using Thread extended MAC for hostname.
I: 315 [ZCL]Using ZAP configuration...
D: 319 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 327 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 335 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 341 [DMG]AccessControlCluster: initializing
D: 346 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b50
D: 352 [DL]Boot reason: 1
D: 354 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 359 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 58d01dac
D: 365 [EVL]LogEvent event number: 0x0000000000020000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000016D
I: 379 [ZCL]Initiating Admin Commissioning cluster.
D: 384 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 555a74a6
D: 390 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 7dcf6cd7
D: 396 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 7dcf6cd8
I: 403 [ZCL]On/Off set value: 1 0
I: 406 [ZCL]On/off already set to new value
D: 410 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 23b72b98
I: 416 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 422 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 431 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:22351
D: 437 [SC]Assigned local session key ID 22351
D: 441 [SC]Waiting for PBKDF param request
D: 445 [DL]CHIPoBLE advertising set to on
I: 449 [DIS]Updating services using commissioning mode 1
D: 454 [DL]Using Thread extended MAC for hostname.
D: 459 [DL]Using Thread extended MAC for hostname.
I: 463 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 473 [DIS]Failed to advertise commissionable node: 3
E: 477 [DIS]Failed to finalize service update: 1c
I: 482 [DIS]Updating services using commissioning mode 1
D: 487 [DL]Using Thread extended MAC for hostname.
D: 492 [DL]Using Thread extended MAC for hostname.
I: 497 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 506 [DIS]Failed to advertise commissionable node: 3
E: 511 [DIS]Failed to finalize service update: 1c
I: 515 [DIS]Delaying proxy of operational discovery: missing delegate
I: 521 [IN]CASE Server enabling CASE session setups
D: 526 [IN]SecureSession[0x20003708]: Allocated Type:2 LSID:22352
D: 532 [SC]Allocated SecureSession (0x20003708) - waiting for Sigma1 msg
I: 538 [SVR]Joining Multicast groups
D: 542 [ZCL]Emitting StartUp event
D: 545 [EVL]LogEvent event number: 0x0000000000020001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000221
I: 559 [SVR]Server Listening...
I: 562 [DL]Device Configuration:
I: 565 [DL]  Serial Number: 11223344556677889900
I: 569 [DL]  Vendor Id: 65521 (0xFFF1)
I: 573 [DL]  Product Id: 32773 (0x8005)
I: 576 [DL]  Hardware Version: 0
I: 580 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 585 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 592 [DL]  Manufacturing Date: (not set)
I: 596 [DL]  Device Type: 65535 (0xFFFF)
I: 600 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 604 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 611 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 620 [SVR]Manual pairing code: [34970112332]
I: 625 [DL]CHIP task running
I: 629 [DL]CHIPoBLE advertising started
D: 633 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to a42345de
I: 640 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 644 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 23b72b99
I: 651 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 657 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 665 [DL]NFC Tag emulation started
I: 13477 [DL]BLE connection established (ConnId: 0x00)
I: 13482 [DL]Current number of connections: 1/2
I: 13486 [DL]CHIPoBLE advertising stopped
I: 13490 [DL]NFC Tag emulation stopped
W: Ignoring data for unknown channel ID 0x003a
D: 14426 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 14433 [BLE]local and remote recv window sizes = 5
I: 14437 [BLE]selected BTP version 4
I: 14441 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 14546 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 14550 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 14558 [IN]BLE EndPoint 0x20012270 Connection Complete
I: 14563 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 14605 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 14614 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 14621 [EM]>>> [E:16623r M:70809559] (U) Msg RX from 0:5189CC053F0F13BA [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 14633 [EM]Handling via exchange: 16623r, Delegate: 0x20005834
D: 14639 [SC]Received PBKDF param request
D: 14643 [SC]Peer assigned session ID 64167
D: 14646 [SC]Found MRP parameters in the message
D: 14651 [SC]Including MRP parameters in PBKDF param response
I: 14657 [EM]<<< [E:16623r M:154641172] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 14669 [IN](U) Sending msg 154641172 to IP address 'BLE'
D: 14674 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 14682 [SC]Sent PBKDF param response
D: 14725 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 14786 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 14793 [EM]>>> [E:16623r M:70809560] (U) Msg RX from 0:5189CC053F0F13BA [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 14804 [EM]Found matching exchange: 16623r, Delegate: 0x20005834
D: 14810 [SC]Received spake2p msg1
I: 16746 [EM]<<< [E:16623r M:154641173] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 16757 [IN](U) Sending msg 154641173 to IP address 'BLE'
D: 16762 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
D: 16770 [SC]Sent spake2p msg2
E: 16773 [DL]Long dispatch time: 1987 ms, for event type 16388
D: 16855 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 16886 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 16893 [EM]>>> [E:16623r M:70809561] (U) Msg RX from 0:5189CC053F0F13BA [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 16904 [EM]Found matching exchange: 16623r, Delegate: 0x20005834
D: 16910 [SC]Received spake2p msg3
D: 16914 [SC]Sending status report. Protocol code 0, exchange 16623
I: 16920 [EM]<<< [E:16623r M:154641174] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 16931 [IN](U) Sending msg 154641174 to IP address 'BLE'
D: 16937 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 16945 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive'
D: 16953 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:22351
D: 16960 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:22351 PSID:64167!
I: 16968 [SVR]Commissioning completed session establishment step
I: 16974 [DIS]Updating services using commissioning mode 0
D: 16980 [DL]Using Thread extended MAC for hostname.
D: 16985 [DL]Using Thread extended MAC for hostname.
I: 16990 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 17000 [DIS]Failed to advertise extended commissionable node: 3
D: 17006 [DIS]Scheduling extended discovery timeout in 900s
E: 17011 [DIS]Failed to finalize service update: 1c
D: 17016 [DL]CHIPoBLE advertising set to off
I: 17020 [SVR]Device completed Rendezvous process
E: 17024 [DL]Long dispatch time: 138 ms, for event type 16388
D: 17030 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17038 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17046 [EM]>>> [E:16624r M:110087012] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17056 [EM]Handling via exchange: 16624r, Delegate: 0x2000fc3c
D: 17062 [IM]Received Read request
D: 17066 [DMG]IM RH moving to [GeneratingReports]
D: 17070 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17079 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 17084 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 17093 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 17099 [EM]<<< [E:16624r M:118289807] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17109 [IN](S) Sending msg 118289807 on secure session with LSID: 22351
D: 17116 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
D: 17123 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 17128 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 17135 [DMG]IM RH moving to [AwaitingDestruction]
D: 17140 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 17156 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17164 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17172 [EM]>>> [E:16625r M:110087013] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17182 [EM]Handling via exchange: 16625r, Delegate: 0x2000fc3c
D: 17188 [IM]Received Read request
D: 17192 [DMG]IM RH moving to [GeneratingReports]
D: 17196 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17205 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 17210 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 17220 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 17228 [EM]<<< [E:16625r M:118289808] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17238 [IN](S) Sending msg 118289808 on secure session with LSID: 22351
D: 17244 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 17252 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 17256 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 17264 [DMG]IM RH moving to [AwaitingDestruction]
D: 17268 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 17305 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17313 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 193)
D: 17366 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17374 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17382 [EM]>>> [E:16626r M:110087014] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17392 [EM]Handling via exchange: 16626r, Delegate: 0x2000fc3c
D: 17398 [IM]Received Read request
D: 17402 [DMG]IM RH moving to [GeneratingReports]
D: 17406 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17415 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 17420 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 17430 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 17436 [EM]<<< [E:16626r M:118289809] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17446 [IN](S) Sending msg 118289809 on secure session with LSID: 22351
D: 17452 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 17460 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 17464 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 17472 [DMG]IM RH moving to [AwaitingDestruction]
D: 17476 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 17516 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17524 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17532 [EM]>>> [E:16627r M:110087015] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17542 [EM]Handling via exchange: 16627r, Delegate: 0x2000fc3c
D: 17548 [IM]Received Read request
D: 17552 [DMG]IM RH moving to [GeneratingReports]
D: 17556 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17565 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 17570 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 17579 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 17586 [EM]<<< [E:16627r M:118289810] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17596 [IN](S) Sending msg 118289810 on secure session with LSID: 22351
D: 17602 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
D: 17610 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 17614 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 17622 [DMG]IM RH moving to [AwaitingDestruction]
D: 17626 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 17696 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17704 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17712 [EM]>>> [E:16628r M:110087016] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17722 [EM]Handling via exchange: 16628r, Delegate: 0x2000fc3c
D: 17728 [IM]Received Read request
D: 17732 [DMG]IM RH moving to [GeneratingReports]
D: 17736 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17745 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 17750 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 17760 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 17768 [EM]<<< [E:16628r M:118289811] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17778 [IN](S) Sending msg 118289811 on secure session with LSID: 22351
D: 17784 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 17792 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 17796 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 17804 [DMG]IM RH moving to [AwaitingDestruction]
D: 17808 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 17846 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17853 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 193)
D: 17906 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17914 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17922 [EM]>>> [E:16629r M:110087017] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 17932 [EM]Handling via exchange: 16629r, Delegate: 0x2000fc3c
D: 17938 [IM]Received Read request
D: 17942 [DMG]IM RH moving to [GeneratingReports]
D: 17946 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 17955 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 17960 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 17970 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 17976 [EM]<<< [E:16629r M:118289812] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 17986 [IN](S) Sending msg 118289812 on secure session with LSID: 22351
D: 17992 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 18000 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 18004 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 18012 [DMG]IM RH moving to [AwaitingDestruction]
D: 18016 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 18055 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18064 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18072 [EM]>>> [E:16630r M:110087018] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 18082 [EM]Handling via exchange: 16630r, Delegate: 0x2000fc3c
D: 18088 [IM]Received Read request
D: 18094 [DMG]IM RH moving to [GeneratingReports]
D: 18099 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 18107 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 18112 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 18122 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 18127 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 18136 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 18141 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 18150 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 18155 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 18164 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 18169 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 18178 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 18183 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 18192 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 18197 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 18206 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 18212 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 18221 [DMG]<RE> Sending report (payload has 228 bytes)...
I: 18228 [EM]<<< [E:16630r M:118289813] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 18238 [IN](S) Sending msg 118289813 on secure session with LSID: 22351
D: 18244 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 18252 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 18257 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 18264 [DMG]IM RH moving to [AwaitingDestruction]
D: 18269 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 18296 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18303 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 18356 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18364 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18372 [EM]>>> [E:16631r M:110087019] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 18383 [EM]Handling via exchange: 16631r, Delegate: 0x2000fc3c
D: 18389 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 18397 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 18402 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b51
D: 18409 [DMG]Command handler moving to [ Preparing]
D: 18414 [DMG]Command handler moving to [AddingComm]
D: 18419 [DMG]Command handler moving to [AddedComma]
D: 18424 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18431 [EM]<<< [E:16631r M:118289814] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 18442 [IN](S) Sending msg 118289814 on secure session with LSID: 22351
D: 18449 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 18456 [DMG]Command handler moving to [CommandSen]
D: 18461 [DMG]Command handler moving to [AwaitingDe]
E: 18465 [DL]Long dispatch time: 101 ms, for event type 16388
D: 18505 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18514 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18522 [EM]>>> [E:16632r M:110087020] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 18533 [EM]Handling via exchange: 16632r, Delegate: 0x2000fc3c
D: 18539 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 18556 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b52
D: 18563 [DMG]Command handler moving to [ Preparing]
D: 18568 [DMG]Command handler moving to [AddingComm]
D: 18573 [DMG]Command handler moving to [AddedComma]
D: 18578 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18585 [EM]<<< [E:16632r M:118289815] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 18596 [IN](S) Sending msg 118289815 on secure session with LSID: 22351
D: 18602 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 18610 [DMG]Command handler moving to [CommandSen]
D: 18615 [DMG]Command handler moving to [AwaitingDe]
E: 18619 [DL]Long dispatch time: 105 ms, for event type 16388
D: 18656 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18664 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18672 [EM]>>> [E:16633r M:110087021] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 18683 [EM]Handling via exchange: 16633r, Delegate: 0x2000fc3c
D: 18689 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 18697 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 18703 [DMG]Command handler moving to [ Preparing]
D: 18707 [DMG]Command handler moving to [AddingComm]
D: 18712 [DMG]Command handler moving to [AddedComma]
D: 18717 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18726 [EM]<<< [E:16633r M:118289816] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 18737 [IN](S) Sending msg 118289816 on secure session with LSID: 22351
D: 18744 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 18752 [DMG]Command handler moving to [CommandSen]
D: 18757 [DMG]Command handler moving to [AwaitingDe]
D: 18835 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18843 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 18956 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18963 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 19076 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19084 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19092 [EM]>>> [E:16634r M:110087022] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 19103 [EM]Handling via exchange: 16634r, Delegate: 0x2000fc3c
D: 19109 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 19117 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 19122 [DMG]Command handler moving to [ Preparing]
D: 19127 [DMG]Command handler moving to [AddingComm]
D: 19132 [DMG]Command handler moving to [AddedComma]
D: 19137 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 19146 [EM]<<< [E:16634r M:118289817] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 19157 [IN](S) Sending msg 118289817 on secure session with LSID: 22351
D: 19164 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19171 [DMG]Command handler moving to [CommandSen]
D: 19176 [DMG]Command handler moving to [AwaitingDe]
D: 19256 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19263 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19376 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19383 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
D: 19495 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19504 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19512 [EM]>>> [E:16635r M:110087023] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 19523 [EM]Handling via exchange: 16635r, Delegate: 0x2000fc3c
D: 19529 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 19537 [ZCL]OpCreds: Received an AttestationRequest command
I: 19573 [ZCL]OpCreds: AttestationRequest successful.
D: 19578 [DMG]Command handler moving to [ Preparing]
D: 19582 [DMG]Command handler moving to [AddingComm]
D: 19587 [DMG]Command handler moving to [AddedComma]
D: 19592 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 19602 [EM]<<< [E:16635r M:118289818] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 19613 [IN](S) Sending msg 118289818 on secure session with LSID: 22351
D: 19620 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19628 [DMG]Command handler moving to [CommandSen]
D: 19632 [DMG]Command handler moving to [AwaitingDe]
E: 19637 [DL]Long dispatch time: 133 ms, for event type 16388
D: 19736 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19743 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19856 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19863 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235)
D: 19976 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19984 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19992 [EM]>>> [E:16636r M:110087024] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 20003 [EM]Handling via exchange: 16636r, Delegate: 0x2000fc3c
D: 20009 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 20017 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 20022 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b53
D: 20029 [DMG]Command handler moving to [ Preparing]
D: 20033 [DMG]Command handler moving to [AddingComm]
D: 20038 [DMG]Command handler moving to [AddedComma]
D: 20043 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20050 [EM]<<< [E:16636r M:118289819] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20061 [IN](S) Sending msg 118289819 on secure session with LSID: 22351
D: 20068 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 20075 [DMG]Command handler moving to [CommandSen]
D: 20080 [DMG]Command handler moving to [AwaitingDe]
E: 20085 [DL]Long dispatch time: 101 ms, for event type 16388
D: 20156 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21596 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21604 [EM]>>> [E:16637r M:110087025] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 21615 [EM]Handling via exchange: 16637r, Delegate: 0x2000fc3c
D: 21621 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 21629 [ZCL]OpCreds: Received a CSRRequest command
D: 21634 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 21828 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 21864 [ZCL]OpCreds: CSRRequest successful.
D: 21868 [DMG]Command handler moving to [ Preparing]
D: 21873 [DMG]Command handler moving to [AddingComm]
D: 21878 [DMG]Command handler moving to [AddedComma]
D: 21883 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 21891 [EM]<<< [E:16637r M:118289820] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 21902 [IN](S) Sending msg 118289820 on secure session with LSID: 22351
D: 21909 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21916 [DMG]Command handler moving to [CommandSen]
D: 21921 [DMG]Command handler moving to [AwaitingDe]
E: 21926 [DL]Long dispatch time: 330 ms, for event type 16388
D: 22016 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22023 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138)
D: 22135 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22144 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 22256 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22265 [EM]>>> [E:16638r M:110087026] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 22276 [EM]Handling via exchange: 16638r, Delegate: 0x2000fc3c
D: 22282 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 22290 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 22353 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 22358 [DMG]Command handler moving to [ Preparing]
D: 22363 [DMG]Command handler moving to [AddingComm]
D: 22367 [DMG]Command handler moving to [AddedComma]
D: 22372 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 22380 [EM]<<< [E:16638r M:118289821] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22391 [IN](S) Sending msg 118289821 on secure session with LSID: 22351
D: 22397 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 22405 [DMG]Command handler moving to [CommandSen]
D: 22410 [DMG]Command handler moving to [AwaitingDe]
E: 22414 [DL]Long dispatch time: 158 ms, for event type 16388
D: 22495 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22504 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 22616 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22625 [EM]>>> [E:16639r M:110087027] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 22636 [EM]Handling via exchange: 16639r, Delegate: 0x2000fc3c
D: 22643 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 22650 [ZCL]OpCreds: Received an AddNOC command
I: 22657 [FP]Validating NOC chain
I: 22718 [FP]NOC chain validation successful
I: 22722 [FP]Added new fabric at index: 0x1
I: 22726 [FP]Assigned compressed fabric ID: 0x9A40BE2EC5AFB8A2, node ID: 0x000000009CCEEEE9
I: 22734 [TS]Last Known Good Time: 2023-01-25T11:24:03
I: 22739 [TS]New proposed Last Known Good Time: 2023-02-01T07:56:39
I: 22745 [TS]Updating pending Last Known Good Time to 2023-02-01T07:56:39
D: 22752 [DMG]Endpoint 0, Cluster 0x0000_003E update version to d1ec6d1e
D: 22758 [DMG]Endpoint 0, Cluster 0x0000_003E update version to d1ec6d1f
D: 22797 [EVL]LogEvent event number: 0x0000000000020002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000590C
I: 22811 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x3A5C47E77ABF1A5D
D: 22819 [DL]Using Thread extended MAC for hostname.
I: 22824 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
D: 22831 [DMG]Endpoint 0, Cluster 0x0000_003E update version to d1ec6d20
D: 22837 [DMG]Endpoint 0, Cluster 0x0000_003E update version to d1ec6d21
D: 22844 [DMG]Command handler moving to [ Preparing]
D: 22848 [DMG]Command handler moving to [AddingComm]
D: 22853 [DMG]Command handler moving to [AddedComma]
I: 22858 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 22864 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 22872 [EM]<<< [E:16639r M:118289822] (S) Msg TX to 1:FFFFFFFB00000000 [B8A2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22883 [IN](S) Sending msg 118289822 on secure session with LSID: 22351
D: 22889 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22897 [DMG]Command handler moving to [CommandSen]
D: 22901 [DMG]Command handler moving to [AwaitingDe]
E: 22906 [DL]Long dispatch time: 290 ms, for event type 16388
D: 22975 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22984 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22992 [EM]>>> [E:16640r M:110087028] (S) Msg RX from 1:FFFFFFFB00000000 [B8A2] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 23003 [EM]Handling via exchange: 16640r, Delegate: 0x2000fc3c
D: 23009 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 23023 [DMG]Command handler moving to [ Preparing]
D: 23028 [DMG]Command handler moving to [AddingComm]
D: 23032 [DMG]Command handler moving to [AddedComma]
D: 23037 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b54
D: 23044 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 23051 [EM]<<< [E:16640r M:118289823] (S) Msg TX to 1:FFFFFFFB00000000 [B8A2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 23062 [IN](S) Sending msg 118289823 on secure session with LSID: 22351
D: 23068 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 23076 [DMG]Command handler moving to [CommandSen]
D: 23081 [DMG]Command handler moving to [AwaitingDe]
E: 23085 [DL]Long dispatch time: 101 ms, for event type 16388
D: 23156 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23164 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 23172 [EM]>>> [E:16641r M:110087029] (S) Msg RX from 1:FFFFFFFB00000000 [B8A2] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 23183 [EM]Handling via exchange: 16641r, Delegate: 0x2000fc3c
D: 23189 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 23207 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 23214 [DL]OpenThread State Changed (Flags: 0x100fc100)
D: 23219 [DL]   Network Name: MyHome1551423246
D: 23224 [DL]   PAN Id: 0xF155
D: 23227 [DL]   Extended PAN Id: 0x9AF908EE8CB04C73
D: 23231 [DL]   Channel: 25
D: 23234 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 23239 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 23244 [DL]   Device Role: DETACHED
D: 23247 [DL]   Thread Unicast Addresses:
D: 23251 [DL]        fdde:ad00:beef:0:3b68:d297:6b7d:adc0/64 valid
D: 23257 [DL]        fe80::a8a2:f9de:8800:152f/64 valid preferred
D: 23962 [DL]OpenThread State Changed (Flags: 0x00000100)
I: 24586 [DL]SRP Client was started, detected server: fd53:69aa:0a11:0000:56f3:fadf:52fd:9ccc
D: 24595 [DL]OpenThread State Changed (Flags: 0x301032b7)
D: 24600 [DL]   Device Role: CHILD
D: 24603 [DL]   Partition Id: 0x5BF0EA5
D: 24607 [DL]   Thread Unicast Addresses:
D: 24611 [DL]        fd53:69aa:a11:0:7124:e099:b72a:33d/64 valid preferred
D: 24618 [DL]        fd9a:f908:ee8c::ff:fe00:dc01/64 valid rloc
D: 24623 [DL]        fd9a:f908:ee8c:0:3b68:d297:6b7d:adc0/64 valid
D: 24629 [DL]        fe80::a8a2:f9de:8800:152f/64 valid preferred
D: 24636 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 24641 [DL]   Thread Unicast Addresses:
D: 24645 [DL]        fd53:69aa:a11:0:7124:e099:b72a:33d/64 valid preferred
D: 24652 [DL]        fd9a:f908:ee8c::ff:fe00:dc01/64 valid rloc
D: 24658 [DL]        fd9a:f908:ee8c:0:3b68:d297:6b7d:adc0/64 valid
D: 24664 [DL]        fe80::a8a2:f9de:8800:152f/64 valid preferred
D: 24671 [DMG]Command handler moving to [ Preparing]
D: 24675 [DMG]Command handler moving to [AddingComm]
D: 24680 [DMG]Command handler moving to [AddedComma]
D: 24685 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b55
D: 24691 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 24699 [EM]<<< [E:16641r M:118289824] (S) Msg TX to 1:FFFFFFFB00000000 [B8A2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24710 [IN](S) Sending msg 118289824 on secure session with LSID: 22351
D: 24716 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 24724 [DMG]Command handler moving to [CommandSen]
D: 24729 [DMG]Command handler moving to [AwaitingDe]
D: 24734 [DL]Using Thread extended MAC for hostname.
I: 24738 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
I: 24745 [SVR]Operational advertising enabled
D: 24836 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 25394 [DL]SRP update succeeded
I: 25397 [DIS]Setting operational delegate post init
I: 25405 [SWU]Stopping the watchdog timer
I: 25409 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 25415 [DIS]Updating services using commissioning mode 0
D: 25420 [DL]Using Thread extended MAC for hostname.
I: 25425 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
I: 25432 [DL]advertising srp service: 9A40BE2EC5AFB8A2-000000009CCEEEE9._matter._tcp
D: 25440 [DL]Using Thread extended MAC for hostname.
I: 25446 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 25455 [DL]advertising srp service: 63C5FEEE153A65DD._matterc._udp
D: 25462 [DMG]Endpoint 0, Cluster 0x0000_002A update version to d9b02b0c
D: 25468 [DMG]Endpoint 0, Cluster 0x0000_002A update version to d9b02b0d
D: 26565 [DL]SRP update succeeded
D: 27296 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 27305 [EM]>>> [E:16642r M:70809562] (U) Msg RX from 0:6CE24ED4F0574BEA [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 27316 [EM]Handling via exchange: 16642r, Delegate: 0x200042c0
I: 27322 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004fd0
I: 27329 [IN]CASE Server disabling CASE session setups
I: 27334 [EM]<<< [E:16642r M:154641175 (Ack:70809562)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 27347 [IN](U) Sending msg 154641175 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
D: 27357 [EM]Flushed pending ack for MessageCounter:70809562 on exchange 16642r
I: 27365 [SC]Received Sigma1 msg
D: 27368 [SC]Found MRP parameters in the message
D: 27373 [SC]Peer assigned session key ID 64168
I: 27380 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x000000009CCEEEE9
D: 27606 [SC]Including MRP parameters
I: 27610 [EM]<<< [E:16642r M:154641176 (Ack:70809562)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 27622 [IN](U) Sending msg 154641176 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
I: 27633 [SC]Sent Sigma2 msg
D: 28038 [EM]Retransmitting MessageCounter:154641176 on exchange 16642r Send Cnt 1
I: 28045 [IN](U) Sending msg 154641176 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
D: 28389 [EM]Retransmitting MessageCounter:154641176 on exchange 16642r Send Cnt 2
I: 28397 [IN](U) Sending msg 154641176 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
I: 28903 [EM]>>> [E:16642r M:70809563 (Ack:154641176)] (U) Msg RX from 0:6CE24ED4F0574BEA [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D: 28915 [EM]Found matching exchange: 16642r, Delegate: 0x200042dc
D: 28921 [EM]Rxd Ack; Removing MessageCounter:154641176 from Retrans Table on exchange 16642r
I: 28930 [EM]<<< [E:16642r M:154641177 (Ack:70809563)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 28943 [IN](U) Sending msg 154641177 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
D: 28953 [EM]Flushed pending ack for MessageCounter:70809563 on exchange 16642r
I: 28960 [SC]Received Sigma3 msg
E: 28966 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
D: 29263 [SC]Sending status report. Protocol code 0, exchange 16642
I: 29270 [EM]<<< [E:16642r M:154641178 (Ack:70809563)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 29282 [IN](U) Sending msg 154641178 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
I: 29294 [SC]SecureSession[0x20003708]: Moving from state 'kEstablishing' --> 'kActive'
D: 29302 [IN]SecureSession[0x20003708]: Activated - Type:2 LSID:22352
D: 29308 [IN]New secure session activated for device <3A5C47E77ABF1A5D, 1>, LSID:22352 PSID:64168!
I: 29317 [IN]CASE Session established to peer: <3A5C47E77ABF1A5D, 1>
I: 29323 [IN]CASE Server enabling CASE session setups
D: 29328 [IN]SecureSession[0x200037c0]: Allocated Type:2 LSID:22353
D: 29335 [SC]Allocated SecureSession (0x200037c0) - waiting for Sigma1 msg
I: 29403 [EM]>>> [E:16643r M:216231075] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 29416 [EM]Handling via exchange: 16643r, Delegate: 0x2000fc3c
D: 29422 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
I: 29430 [FS]GeneralCommissioning: Received CommissioningComplete
I: 29550 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 29743 [TS]Committing Last Known Good Time to storage: 2023-02-01T07:56:39
I: 29807 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x9A40BE2EC5AFB8A2, FabricId 0000000000000001, NodeId 000000009CCEEEE9, VendorId 0x1349
I: 29849 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 29855 [FS]Fail-safe cleanly disarmed
D: 29859 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 22934b56
D: 29866 [DMG]Command handler moving to [ Preparing]
D: 29870 [DMG]Command handler moving to [AddingComm]
D: 29875 [DMG]Command handler moving to [AddedComma]
D: 29880 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 29887 [EM]<<< [E:16643r M:84337419 (Ack:216231075)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 29900 [IN](S) Sending msg 84337419 on secure session with LSID: 22352
D: 29907 [DMG]Command handler moving to [CommandSen]
D: 29912 [DMG]Command handler moving to [AwaitingDe]
I: 29917 [SWU]Device commissioned, schedule a default provider query
I: 29923 [SVR]Commissioning completed successfully
I: 29928 [DIS]Updating services using commissioning mode 0
D: 29933 [DL]Using Thread extended MAC for hostname.
I: 29938 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
D: 29945 [DL]Using Thread extended MAC for hostname.
I: 29951 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
D: 29961 [IN]Expiring all PASE sessions
D: 29964 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:22351
I: 29971 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction'
D: 29979 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:22351
D: 29985 [IN]Clearing BLE pending packets.
I: 29989 [BLE]Releasing end point's BLE connection back to application.
I: 29995 [DL]Closing BLE GATT connection (ConnId 00)
D: 30001 [ZCL]Commissioning complete, notify platform driver to persist network credentials.
E: 30035 [DL]Long dispatch time: 118 ms, for event type 32781
D: 30041 [EM]Retransmitting MessageCounter:154641178 on exchange 16642r Send Cnt 1
I: 30049 [IN](U) Sending msg 154641178 to IP address 'UDP:[fdf9:8ee:8cb0:4c73:d3:ac0a:2074:af3f]:55456'
E: not connected!
I: 30062 [EM]>>> [E:16642r M:70809564 (Ack:154641178)] (U) Msg RX from 0:6CE24ED4F0574BEA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 30074 [EM]Found matching exchange: 16642r, Delegate: (nil)
D: 30080 [EM]Rxd Ack; Removing MessageCounter:154641178 from Retrans Table on exchange 16642r
D: 30089 [DL]ConnId: 0x00, New CCCD value: 0x0000
E: 30093 [BLE]no endpoint for unsub recvd
I: 30098 [EM]>>> [E:16643r M:216231076 (Ack:84337419)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 30110 [EM]Found matching exchange: 16643r, Delegate: (nil)
D: 30116 [EM]Rxd Ack; Removing MessageCounter:84337419 from Retrans Table on exchange 16643r
I: 30198 [EM]>>> [E:16644r M:216231077] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 30208 [EM]Handling via exchange: 16644r, Delegate: 0x2000fc3c
D: 30214 [IM]Received Read request
D: 30218 [DMG]IM RH moving to [GeneratingReports]
D: 30222 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 30231 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 30236 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 30247 [DMG]<RE> Sending report (payload has 151 bytes)...
I: 30253 [EM]<<< [E:16644r M:84337420 (Ack:216231077)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 30265 [IN](S) Sending msg 84337420 on secure session with LSID: 22352
D: 30272 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 30277 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 30285 [DMG]IM RH moving to [AwaitingDestruction]
D: 30290 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 30297 [EM]>>> [E:16642r M:70809565 (Ack:154641178)] (U) Msg RX from 0:6CE24ED4F0574BEA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 30391 [EM]>>> [E:16644r M:216231078 (Ack:84337420)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 30403 [EM]Found matching exchange: 16644r, Delegate: (nil)
D: 30410 [EM]Rxd Ack; Removing MessageCounter:84337420 from Retrans Table on exchange 16644r
I: 30421 [EM]>>> [E:16645r M:216231079] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 30431 [EM]Handling via exchange: 16645r, Delegate: 0x2000fc3c
D: 30437 [IM]Received Read request
D: 30440 [DMG]IM RH moving to [GeneratingReports]
I: 30445 [DL]BLE GAP connection terminated (reason 0x22)
I: 30450 [DL]Current number of connections: 0/2
D: 30454 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 30463 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 30468 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 30477 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 30483 [EM]<<< [E:16645r M:84337421 (Ack:216231079)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 30495 [IN](S) Sending msg 84337421 on secure session with LSID: 22352
D: 30502 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 30507 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 30515 [DMG]IM RH moving to [AwaitingDestruction]
D: 30520 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 30626 [EM]>>> [E:16645r M:216231080 (Ack:84337421)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 30640 [EM]Found matching exchange: 16645r, Delegate: (nil)
D: 30646 [EM]Rxd Ack; Removing MessageCounter:84337421 from Retrans Table on exchange 16645r
I: 30655 [EM]>>> [E:16646r M:216231081] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 30665 [EM]Handling via exchange: 16646r, Delegate: 0x2000fc3c
D: 30671 [IM]Received Read request
D: 30674 [DMG]IM RH moving to [GeneratingReports]
D: 30679 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 30688 [DMG]<RE:Run> Cluster 1d, Attribute 0 is dirty
D: 30693 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
D: 30702 [DMG]<RE> Sending report (payload has 71 bytes)...
I: 30708 [EM]<<< [E:16646r M:84337422 (Ack:216231081)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 30719 [IN](S) Sending msg 84337422 on secure session with LSID: 22352
D: 30727 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 30732 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 30740 [DMG]IM RH moving to [AwaitingDestruction]
D: 30744 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 30850 [EM]>>> [E:16646r M:216231082 (Ack:84337422)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 30864 [EM]Found matching exchange: 16646r, Delegate: (nil)
D: 30870 [EM]Rxd Ack; Removing MessageCounter:84337422 from Retrans Table on exchange 16646r
I: 30879 [EM]>>> [E:16647r M:216231083] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 30889 [EM]Handling via exchange: 16647r, Delegate: 0x2000fc3c
D: 30895 [IM]Received Read request
D: 30899 [DMG]IM RH moving to [GeneratingReports]
D: 30904 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 30912 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 30917 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0)
D: 30926 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 30932 [EM]<<< [E:16647r M:84337423 (Ack:216231083)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 30944 [IN](S) Sending msg 84337423 on secure session with LSID: 22352
D: 30951 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 30956 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 30964 [DMG]IM RH moving to [AwaitingDestruction]
D: 30968 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 31146 [EM]>>> [E:16647r M:216231084 (Ack:84337423)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 31160 [EM]Found matching exchange: 16647r, Delegate: (nil)
D: 31166 [EM]Rxd Ack; Removing MessageCounter:84337423 from Retrans Table on exchange 16647r
I: 31175 [EM]>>> [E:16648r M:216231085] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 31185 [EM]Handling via exchange: 16648r, Delegate: 0x2000fc3c
D: 31191 [IM]Received Read request
D: 31195 [DMG]IM RH moving to [GeneratingReports]
D: 31199 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 31208 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 31213 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
D: 31222 [DMG]<RE> Sending report (payload has 176 bytes)...
I: 31229 [EM]<<< [E:16648r M:84337424 (Ack:216231085)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 31240 [IN](S) Sending msg 84337424 on secure session with LSID: 22352
D: 31248 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 31253 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 31261 [DMG]IM RH moving to [AwaitingDestruction]
D: 31266 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 31650 [EM]Retransmitting MessageCounter:84337424 on exchange 16648r Send Cnt 1
I: 31658 [IN](S) Sending msg 84337424 on secure session with LSID: 22352
I: 31729 [EM]>>> [E:16648r M:216231086 (Ack:84337424)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 31743 [EM]Found matching exchange: 16648r, Delegate: (nil)
D: 31748 [EM]Rxd Ack; Removing MessageCounter:84337424 from Retrans Table on exchange 16648r
I: 31758 [EM]>>> [E:16649r M:216231087] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 31770 [EM]Handling via exchange: 16649r, Delegate: 0x2000fc3c
D: 31775 [IM]Received Read request
D: 31779 [DMG]IM RH moving to [GeneratingReports]
D: 31784 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 31792 [DMG]<RE:Run> Cluster 8, Attribute fffc is dirty
D: 31797 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
D: 31806 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 31813 [EM]<<< [E:16649r M:84337425 (Ack:216231087)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 31824 [IN](S) Sending msg 84337425 on secure session with LSID: 22352
D: 31832 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 31836 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 31844 [DMG]IM RH moving to [AwaitingDestruction]
D: 31849 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 31855 [EM]>>> [E:16648r M:216231088 (Ack:84337424)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 31963 [EM]>>> [E:16649r M:216231089 (Ack:84337425)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 31977 [EM]Found matching exchange: 16649r, Delegate: (nil)
D: 31983 [EM]Rxd Ack; Removing MessageCounter:84337425 from Retrans Table on exchange 16649r
I: 31992 [EM]>>> [E:16650r M:216231090] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 32002 [EM]Handling via exchange: 16650r, Delegate: 0x2000fc3c
D: 32008 [IM]Received Read request
D: 32012 [DMG]IM RH moving to [GeneratingReports]
D: 32017 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 32025 [DMG]<RE:Run> Cluster 6, Attribute fffc is dirty
D: 32030 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
D: 32039 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 32046 [EM]<<< [E:16650r M:84337426 (Ack:216231090)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 32057 [IN](S) Sending msg 84337426 on secure session with LSID: 22352
D: 32064 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 32069 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 32077 [DMG]IM RH moving to [AwaitingDestruction]
D: 32082 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 32141 [EM]>>> [E:16650r M:216231091 (Ack:84337426)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 32156 [EM]Found matching exchange: 16650r, Delegate: (nil)
D: 32161 [EM]Rxd Ack; Removing MessageCounter:84337426 from Retrans Table on exchange 16650r
I: 32170 [EM]>>> [E:16651r M:216231092] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:02 (IM:ReadRequest)
D: 32180 [EM]Handling via exchange: 16651r, Delegate: 0x2000fc3c
D: 32186 [IM]Received Read request
D: 32190 [DMG]IM RH moving to [GeneratingReports]
D: 32195 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 32203 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 32208 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 32218 [DMG]<RE> Sending report (payload has 151 bytes)...
I: 32224 [EM]<<< [E:16651r M:84337427 (Ack:216231092)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:05 (IM:ReportData)
I: 32236 [IN](S) Sending msg 84337427 on secure session with LSID: 22352
D: 32243 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 32248 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 32256 [DMG]IM RH moving to [AwaitingDestruction]
D: 32261 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 32342 [EM]>>> [E:16651r M:216231093 (Ack:84337427)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 32355 [EM]Found matching exchange: 16651r, Delegate: (nil)
D: 32361 [EM]Rxd Ack; Removing MessageCounter:84337427 from Retrans Table on exchange 16651r
I: 32417 [EM]>>> [E:16652r M:216231094] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:0a (IM:TimedRequest)
D: 32428 [EM]Handling via exchange: 16652r, Delegate: 0x2000fc3c
D: 32434 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 16652r
I: 32442 [EM]<<< [E:16652r M:84337428 (Ack:216231094)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:01 (IM:StatusResponse)
I: 32454 [IN](S) Sending msg 84337428 on secure session with LSID: 22352
D: 32462 [DMG]Timed Request time limit 0x000000000000A5DD: handler 0x20010038 exchange 16652r
I: 32555 [EM]>>> [E:16652r M:216231095 (Ack:84337428)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 32567 [EM]Found matching exchange: 16652r, Delegate: 0x20010038
D: 32573 [EM]Rxd Ack; Removing MessageCounter:84337428 from Retrans Table on exchange 16652r
D: 32582 [DMG]Timed following action arrived at 0x0000000000007F46: handler 0x20010038 exchange 16652r
D: 32591 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 16652r
D: 32599 [DMG]Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000
I: 32606 [ZCL]Received command to open commissioning window
D: 32612 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:22354
D: 32618 [SC]Assigned local session key ID 22354
D: 32623 [SC]Waiting for PBKDF param request
I: 32627 [DIS]Updating services using commissioning mode 2
D: 32632 [DL]Using Thread extended MAC for hostname.
I: 32637 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
D: 32644 [DL]Using Thread extended MAC for hostname.
I: 32649 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=0568/02 cm=2
I: 32659 [DL]advertising srp service: CCDF12D7805CAAAE._matterc._udp
I: 32665 [DL]removing srp service: 63C5FEEE153A65DD._matterc._udp
I: 32671 [ZCL]Commissioning window is now open
D: 32675 [DMG]Command handler moving to [ Preparing]
D: 32680 [DMG]Command handler moving to [AddingComm]
D: 32685 [DMG]Command handler moving to [AddedComma]
D: 32689 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 32697 [EM]<<< [E:16652r M:84337429 (Ack:216231095)] (S) Msg TX to 1:3A5C47E77ABF1A5D [B8A2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 32709 [IN](S) Sending msg 84337429 on secure session with LSID: 22352
D: 32717 [DMG]Command handler moving to [CommandSen]
D: 32721 [DMG]Command handler moving to [AwaitingDe]
D: 33093 [EM]Retransmitting MessageCounter:84337429 on exchange 16652r Send Cnt 1
I: 33100 [IN](S) Sending msg 84337429 on secure session with LSID: 22352
I: 33110 [EM]>>> [E:16652r M:216231096 (Ack:84337429)] (S) Msg RX from 1:3A5C47E77ABF1A5D [B8A2] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 33123 [EM]Found matching exchange: 16652r, Delegate: (nil)
D: 33129 [EM]Rxd Ack; Removing MessageCounter:84337429 from Retrans Table on exchange 16652r
D: 33602 [DL]SRP update succeeded
D: 42236 [DL]OpenThread State Changed (Flags: 0x00000064)
D: 42241 [DL]   Device Role: ROUTER
E: 59923 [SWU]No suitable OTA Provider candidate found
I: 59928 [SWU]No provider available
I: 332613 [SVR]Closing pairing window
D: 332616 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:22354
I: 332622 [DIS]Updating services using commissioning mode 0
D: 332628 [DL]Using Thread extended MAC for hostname.
I: 332633 [DIS]Advertise operational node 9A40BE2EC5AFB8A2-000000009CCEEEE9
D: 332640 [DL]Using Thread extended MAC for hostname.
I: 332645 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 332655 [DL]advertising srp service: CCDF12D7805CAAAE._matterc._udp
D: 332661 [DIS]Scheduling extended discovery timeout in 900s
D: 333524 [DL]SRP update succeeded

Fullscreen 03_Google_QR_Code.txt Download

                                                                              
I: 30687 [DL]CHIPoBLE advertising mode changed to slow
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 1, af8
I: data wra: 1, 314


ooting Zephyr OS build v3.2.99-ncs1 ***
[1;I: Init CHIP stack
32muart:~$ : 226 [DL]BLE address: FD:56:38:BE:8B:8D
mI: 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: 252 [DL]OpenThread started: OK
I: 255 [DL]Setting OpenThread device type to ROUTER
I: 260 [SVR]Server initializing...
D: 263 [FP]Initializing FabricTable from persistent storage
I: 269 [TS]Last Known Good Time: 2023-01-25T11:24:03
I: 275 [DMG]AccessControl: initializing
I: 278 [DMG]Examples::AccessControlDelegate::Init
I: 283 [DMG]AccessControl: setting
I: 286 [DMG]DefaultAclStorage: initializing
I: 290 [DMG]DefaultAclStorage: 0 entries loaded
D: 294 [IN]UDP::Init bind&listen port=5540
E: 298 [IN]SO_REUSEPORT failed: 109
D: 302 [IN]UDP::Init bound to port=5540
D: 305 [IN]BLEBase::Init - setting/overriding transport
D: 310 [IN]TransportMgr initialized
D: 318 [DL]Using Thread extended MAC for hostname.
I: 325 [ZCL]Using ZAP configuration...
D: 329 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 338 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 346 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 353 [DMG]AccessControlCluster: initializing
D: 357 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc583588
D: 364 [DL]Boot reason: 1
D: 366 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 370 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to e18e98d9
D: 377 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000178
I: 390 [ZCL]Initiating Admin Commissioning cluster.
D: 395 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to a8d0ac13
D: 402 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to c8665ae5
D: 408 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to c8665ae6
I: 414 [ZCL]On/Off set value: 1 0
I: 417 [ZCL]On/off already set to new value
D: 422 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fe5bebbf
I: 428 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 434 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 444 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:38145
D: 450 [SC]Assigned local session key ID 38145
D: 454 [SC]Waiting for PBKDF param request
D: 458 [DL]CHIPoBLE advertising set to on
I: 462 [DIS]Updating services using commissioning mode 1
D: 467 [DL]Using Thread extended MAC for hostname.
D: 472 [DL]Using Thread extended MAC for hostname.
I: 477 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 486 [DIS]Failed to advertise commissionable node: 3
E: 491 [DIS]Failed to finalize service update: 1c
I: 495 [DIS]Updating services using commissioning mode 1
D: 500 [DL]Using Thread extended MAC for hostname.
D: 505 [DL]Using Thread extended MAC for hostname.
I: 511 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 520 [DIS]Failed to advertise commissionable node: 3
E: 525 [DIS]Failed to finalize service update: 1c
I: 529 [DIS]Delaying proxy of operational discovery: missing delegate
I: 535 [IN]CASE Server enabling CASE session setups
D: 540 [IN]SecureSession[0x20003708]: Allocated Type:2 LSID:38146
D: 546 [SC]Allocated SecureSession (0x20003708) - waiting for Sigma1 msg
I: 552 [SVR]Joining Multicast groups
D: 556 [ZCL]Emitting StartUp event
D: 559 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000000022F
I: 573 [SVR]Server Listening...
I: 576 [DL]Device Configuration:
I: 579 [DL]  Serial Number: 11223344556677889900
I: 584 [DL]  Vendor Id: 65521 (0xFFF1)
I: 587 [DL]  Product Id: 32773 (0x8005)
I: 591 [DL]  Hardware Version: 0
I: 595 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 601 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 608 [DL]  Manufacturing Date: (not set)
I: 612 [DL]  Device Type: 65535 (0xFFFF)
I: 617 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 621 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 628 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 636 [SVR]Manual pairing code: [34970112332]
I: 642 [DL]CHIP task running
I: 646 [DL]CHIPoBLE advertising started
D: 651 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 6530eb55
I: 657 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 662 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fe5bebc0
I: 668 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 674 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 683 [DL]NFC Tag emulation started
I: 30650 [DL]CHIPoBLE advertising mode changed to slow
I: 37021 [DL]BLE connection established (ConnId: 0x00)
I: 37026 [DL]Current number of connections: 1/2
I: 37030 [DL]CHIPoBLE advertising stopped
I: 37034 [DL]NFC Tag emulation stopped
D: 37609 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 37616 [BLE]local and remote recv window sizes = 5
I: 37621 [BLE]selected BTP version 4
I: 37624 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 37707 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 37711 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 37718 [IN]BLE EndPoint 0x20012270 Connection Complete
I: 37724 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 37804 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 37853 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 37860 [EM]>>> [E:49049r M:138475096] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 37872 [EM]Handling via exchange: 49049r, Delegate: 0x20005834
D: 37878 [SC]Received PBKDF param request
D: 37881 [SC]Peer assigned session ID 19992
D: 37885 [SC]Found MRP parameters in the message
D: 37890 [SC]Including MRP parameters in PBKDF param response
I: 37896 [EM]<<< [E:49049r M:182311160] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 37908 [IN](U) Sending msg 182311160 to IP address 'BLE'
D: 37913 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 37921 [SC]Sent PBKDF param response
D: 37999 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38007 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 38145 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38153 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 38161 [EM]>>> [E:49049r M:138475097] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 38172 [EM]Found matching exchange: 49049r, Delegate: 0x20005834
D: 38178 [SC]Received spake2p msg1
I: 40106 [EM]<<< [E:49049r M:182311161] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 40117 [IN](U) Sending msg 182311161 to IP address 'BLE'
D: 40122 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 40129 [SC]Sent spake2p msg2
E: 40132 [DL]Long dispatch time: 1979 ms, for event type 16388
D: 40193 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40200 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 40291 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40298 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40306 [EM]>>> [E:49049r M:138475098] (U) Msg RX from 0:A572A95ADE084B6B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 40317 [EM]Found matching exchange: 49049r, Delegate: 0x20005834
D: 40323 [SC]Received spake2p msg3
D: 40326 [SC]Sending status report. Protocol code 0, exchange 49049
I: 40333 [EM]<<< [E:49049r M:182311162] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 40344 [IN](U) Sending msg 182311162 to IP address 'BLE'
D: 40349 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 40358 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive'
D: 40366 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:38145
D: 40372 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:38145 PSID:19992!
I: 40380 [SVR]Commissioning completed session establishment step
I: 40387 [DIS]Updating services using commissioning mode 0
D: 40392 [DL]Using Thread extended MAC for hostname.
D: 40397 [DL]Using Thread extended MAC for hostname.
I: 40403 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 40412 [DIS]Failed to advertise extended commissionable node: 3
D: 40418 [DIS]Scheduling extended discovery timeout in 900s
E: 40423 [DIS]Failed to finalize service update: 1c
D: 40428 [DL]CHIPoBLE advertising set to off
I: 40432 [SVR]Device completed Rendezvous process
E: 40437 [DL]Long dispatch time: 139 ms, for event type 16388
D: 40443 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40451 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40459 [EM]>>> [E:49050r M:103199849] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 40469 [EM]Handling via exchange: 49050r, Delegate: 0x2000fc3c
D: 40474 [IM]Received Read request
D: 40478 [DMG]IM RH moving to [GeneratingReports]
D: 40483 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 40492 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 40497 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 40506 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 40512 [EM]<<< [E:49050r M:80103682] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 40522 [IN](S) Sending msg 80103682 on secure session with LSID: 38145
D: 40528 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 40536 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 40540 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 40548 [DMG]IM RH moving to [AwaitingDestruction]
D: 40552 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 40632 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40640 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40648 [EM]>>> [E:49051r M:103199850] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 40658 [EM]Handling via exchange: 49051r, Delegate: 0x2000fc3c
D: 40664 [IM]Received Read request
D: 40667 [DMG]IM RH moving to [GeneratingReports]
D: 40672 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 40681 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 40686 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 40695 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 40701 [EM]<<< [E:49051r M:80103683] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 40711 [IN](S) Sending msg 80103683 on secure session with LSID: 38145
D: 40717 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 40725 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 40730 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 40737 [DMG]IM RH moving to [AwaitingDestruction]
D: 40741 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 40778 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40786 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40794 [EM]>>> [E:49052r M:103199851] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 40804 [EM]Handling via exchange: 49052r, Delegate: 0x2000fc3c
D: 40810 [IM]Received Read request
D: 40814 [DMG]IM RH moving to [GeneratingReports]
D: 40818 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 40827 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty
D: 40832 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 40841 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 40847 [EM]<<< [E:49052r M:80103684] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 40857 [IN](S) Sending msg 80103684 on secure session with LSID: 38145
D: 40863 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 40871 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 40876 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 40883 [DMG]IM RH moving to [AwaitingDestruction]
D: 40888 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 40924 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40932 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40940 [EM]>>> [E:49053r M:103199852] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 40950 [EM]Handling via exchange: 49053r, Delegate: 0x2000fc3c
D: 40956 [IM]Received Read request
D: 40960 [DMG]IM RH moving to [GeneratingReports]
D: 40965 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 40973 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty
D: 40978 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 40987 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 40993 [EM]<<< [E:49053r M:80103685] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 41003 [IN](S) Sending msg 80103685 on secure session with LSID: 38145
D: 41010 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 41017 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 41022 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 41029 [DMG]IM RH moving to [AwaitingDestruction]
D: 41034 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 41071 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41078 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 41086 [EM]>>> [E:49054r M:103199853] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 41097 [EM]Handling via exchange: 49054r, Delegate: 0x2000fc3c
D: 41102 [IM]Received Read request
D: 41106 [DMG]IM RH moving to [GeneratingReports]
D: 41111 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 41119 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 41124 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 41133 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 41139 [EM]<<< [E:49054r M:80103686] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 41149 [IN](S) Sending msg 80103686 on secure session with LSID: 38145
D: 41156 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 41163 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 41168 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 41176 [DMG]IM RH moving to [AwaitingDestruction]
D: 41180 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 41217 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41225 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 41233 [EM]>>> [E:49055r M:103199854] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 41243 [EM]Handling via exchange: 49055r, Delegate: 0x2000fc3c
D: 41248 [IM]Received Read request
D: 41252 [DMG]IM RH moving to [GeneratingReports]
D: 41257 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 41266 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 41271 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 41280 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 41288 [EM]<<< [E:49055r M:80103687] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 41298 [IN](S) Sending msg 80103687 on secure session with LSID: 38145
D: 41304 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 41312 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 41317 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 41324 [DMG]IM RH moving to [AwaitingDestruction]
D: 41329 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 41363 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41370 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 41460 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41468 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 41558 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41565 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 41656 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 41663 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 41753 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 41761 [EM]>>> [E:49056r M:103199855] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 41771 [EM]Handling via exchange: 49056r, Delegate: 0x2000fc3c
D: 41777 [IM]Received Read request
D: 41781 [DMG]IM RH moving to [GeneratingReports]
D: 41785 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 41794 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 41799 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 41808 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 41814 [EM]<<< [E:49056r M:80103688] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 41824 [IN](S) Sending msg 80103688 on secure session with LSID: 38145
D: 41831 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 41838 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 41843 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 41851 [DMG]IM RH moving to [AwaitingDestruction]
D: 41855 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 41899 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 42897 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 42904 [EM]>>> [E:49057r M:103199856] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 42915 [EM]Handling via exchange: 49057r, Delegate: 0x2000fc3c
D: 42921 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 49057r
I: 42929 [EM]<<< [E:49057r M:80103689] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 42939 [IN](S) Sending msg 80103689 on secure session with LSID: 38145
D: 42946 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 42954 [DMG]Timed Request time limit 0x000000000000CED9: handler 0x20010038 exchange 49057r
D: 43032 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43040 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43048 [EM]>>> [E:49057r M:103199857] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 43059 [EM]Found matching exchange: 49057r, Delegate: 0x20010038
D: 43065 [DMG]Timed following action arrived at 0x000000000000A839: handler 0x20010038 exchange 49057r
D: 43074 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 49057r
D: 43082 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 43090 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
D: 43095 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc583589
D: 43102 [DMG]Command handler moving to [ Preparing]
D: 43106 [DMG]Command handler moving to [AddingComm]
D: 43111 [DMG]Command handler moving to [AddedComma]
D: 43116 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 43124 [EM]<<< [E:49057r M:80103690] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 43134 [IN](S) Sending msg 80103690 on secure session with LSID: 38145
D: 43141 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 43149 [DMG]Command handler moving to [CommandSen]
D: 43153 [DMG]Command handler moving to [AwaitingDe]
E: 43158 [DL]Long dispatch time: 118 ms, for event type 16388
D: 43212 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43220 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43228 [EM]>>> [E:49058r M:103199858] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 43238 [EM]Handling via exchange: 49058r, Delegate: 0x2000fc3c
D: 43244 [IM]Received Read request
D: 43247 [DMG]IM RH moving to [GeneratingReports]
D: 43252 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 43261 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 43266 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 43275 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 43281 [EM]<<< [E:49058r M:80103691] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 43291 [IN](S) Sending msg 80103691 on secure session with LSID: 38145
D: 43297 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 43305 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 43310 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 43317 [DMG]IM RH moving to [AwaitingDestruction]
D: 43322 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 43392 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43400 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43408 [EM]>>> [E:49059r M:103199859] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 43418 [EM]Handling via exchange: 49059r, Delegate: 0x2000fc3c
D: 43424 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 49059r
I: 43432 [EM]<<< [E:49059r M:80103692] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 43443 [IN](S) Sending msg 80103692 on secure session with LSID: 38145
D: 43449 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 43457 [DMG]Timed Request time limit 0x000000000000D0D1: handler 0x20010038 exchange 49059r
D: 43527 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43535 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43543 [EM]>>> [E:49059r M:103199860] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 43554 [EM]Found matching exchange: 49059r, Delegate: 0x20010038
D: 43560 [DMG]Timed following action arrived at 0x000000000000AA28: handler 0x20010038 exchange 49059r
D: 43569 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 49059r
D: 43577 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 43593 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc58358a
D: 43599 [DMG]Command handler moving to [ Preparing]
D: 43604 [DMG]Command handler moving to [AddingComm]
D: 43609 [DMG]Command handler moving to [AddedComma]
D: 43613 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 43621 [EM]<<< [E:49059r M:80103693] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 43632 [IN](S) Sending msg 80103693 on secure session with LSID: 38145
D: 43638 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 43646 [DMG]Command handler moving to [CommandSen]
D: 43651 [DMG]Command handler moving to [AwaitingDe]
E: 43655 [DL]Long dispatch time: 120 ms, for event type 16388
D: 43707 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43715 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43723 [EM]>>> [E:49060r M:103199861] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 43734 [EM]Handling via exchange: 49060r, Delegate: 0x2000fc3c
D: 43740 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 43747 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 43754 [DMG]Command handler moving to [ Preparing]
D: 43758 [DMG]Command handler moving to [AddingComm]
D: 43763 [DMG]Command handler moving to [AddedComma]
D: 43768 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 43777 [EM]<<< [E:49060r M:80103694] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 43788 [IN](S) Sending msg 80103694 on secure session with LSID: 38145
D: 43794 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 43803 [DMG]Command handler moving to [CommandSen]
D: 43807 [DMG]Command handler moving to [AwaitingDe]
D: 43886 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43894 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 43976 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43984 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44066 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44074 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44157 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44165 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 44172 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 44248 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44255 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 44263 [EM]>>> [E:49061r M:103199862] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44274 [EM]Handling via exchange: 49061r, Delegate: 0x2000fc3c
D: 44281 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 44288 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 44294 [DMG]Command handler moving to [ Preparing]
D: 44299 [DMG]Command handler moving to [AddingComm]
D: 44304 [DMG]Command handler moving to [AddedComma]
D: 44309 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44318 [EM]<<< [E:49061r M:80103695] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44329 [IN](S) Sending msg 80103695 on secure session with LSID: 38145
D: 44335 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44343 [DMG]Command handler moving to [CommandSen]
D: 44348 [DMG]Command handler moving to [AwaitingDe]
D: 44426 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44434 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44516 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44524 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44606 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44614 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44697 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44705 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 44712 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28)
D: 44786 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44795 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 44803 [EM]>>> [E:49062r M:103199863] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44814 [EM]Handling via exchange: 49062r, Delegate: 0x2000fc3c
D: 44820 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 44828 [ZCL]OpCreds: Received an AttestationRequest command
I: 44864 [ZCL]OpCreds: AttestationRequest successful.
D: 44869 [DMG]Command handler moving to [ Preparing]
D: 44873 [DMG]Command handler moving to [AddingComm]
D: 44879 [DMG]Command handler moving to [AddedComma]
D: 44883 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44893 [EM]<<< [E:49062r M:80103696] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44904 [IN](S) Sending msg 80103696 on secure session with LSID: 38145
D: 44911 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 44918 [DMG]Command handler moving to [CommandSen]
D: 44923 [DMG]Command handler moving to [AwaitingDe]
E: 44928 [DL]Long dispatch time: 133 ms, for event type 16388
D: 44966 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 44974 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45056 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45064 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45146 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45154 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45237 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45245 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 45252 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45326 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45334 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90)
D: 45416 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45425 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45433 [EM]>>> [E:49063r M:103199864] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 45444 [EM]Handling via exchange: 49063r, Delegate: 0x2000fc3c
D: 45450 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 45458 [ZCL]OpCreds: Received a CSRRequest command
D: 45463 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 45657 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 45693 [ZCL]OpCreds: CSRRequest successful.
D: 45697 [DMG]Command handler moving to [ Preparing]
D: 45702 [DMG]Command handler moving to [AddingComm]
D: 45707 [DMG]Command handler moving to [AddedComma]
D: 45712 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 45720 [EM]<<< [E:49063r M:80103697] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45731 [IN](S) Sending msg 80103697 on secure session with LSID: 38145
D: 45738 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45745 [DMG]Command handler moving to [CommandSen]
D: 45750 [DMG]Command handler moving to [AwaitingDe]
E: 45755 [DL]Long dispatch time: 330 ms, for event type 16388
D: 45821 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45829 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 45911 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45919 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 46001 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 47666 [DL]BLE GAP connection terminated (reason 0x13)
D: 47672 [IN]Clearing BLE pending packets.
I: 47676 [DL]Current number of connections: 0/2
I: 163095 [FS]Fail-safe timer expired
E: 163098 [SVR]Failsafe timer expired
D: 163102 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:38145
I: 163108 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction'
D: 163117 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:38145
E: 163123 [SVR]Commissioning failed (attempt 1): 32
D: 163130 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:38147
D: 163136 [SC]Assigned local session key ID 38147
D: 163140 [SC]Waiting for PBKDF param request
D: 163144 [DL]CHIPoBLE advertising set to on
I: 163148 [DIS]Updating services using commissioning mode 1
D: 163154 [DL]Using Thread extended MAC for hostname.
D: 163159 [DL]Using Thread extended MAC for hostname.
I: 163164 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 163174 [DIS]Failed to advertise commissionable node: 3
E: 163179 [DIS]Failed to finalize service update: 1c
E: 163184 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 163188 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
I: 163195 [TS]Pending Last Known Good Time: 2023-01-25T11:24:03
I: 163201 [TS]Previous Last Known Good Time: 2023-01-25T11:24:03
I: 163207 [TS]Reverted Last Known Good Time to previous value
D: 163212 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to fc58358b
D: 163219 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 163227 [DL]Long dispatch time: 129 ms, for event type 32782
I: 163233 [FS]Fail-safe cleanly disarmed
I: 163238 [DL]CHIPoBLE advertising started
I: 163244 [DL]NFC Tag emulation started
I: 193243 [DL]CHIPoBLE advertising mode changed to slow

Thanks in advance.

+ I'm sorry.
   I found Marte's post belatedly.
   I'll check this out.

 Matter: Testing the nRF Connect platform with Apple, Google and Samsung ecosystems 

Best regards,

Yunjoo

[Marte Myrvold]

Hi Yunjoo,

Which version of iOS and Android do you have on the phones you used for testing? Which versions do you have of the Apple Home app, Apple HomePod Mini, Google Home app, and Google Nest Hub?

Your Google log shows that you have a different issue than I saw when testing. For Google, the fail-safe timer expires, so the commissioning is terminated. Did you create an integration for your device in the Google Developer Center and specify the device's VID and PID?

I am not able to see why it fails with Apple. The log shows that the device joins the network and is assigned the router role. What does the error on the phone say in English?

Best regards,
Marte