Out of memory (CHIP error 0x0b) when trying to commission Window Covering sample with GHA

[abollaert]

Hi,

I've been playing around with the Matter samples (in particular the window covering sample) to get them to work with the recently released Google Home Matter program.

I've gotten the lighting app example to work, but when I try to commission the window covering example I run into memory issues:

E: 201315 [DMG]Error retrieving data from clusterId: 0x0000_0031, err = b
E: 201613 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b

I already decreased log levels and disabled the shell, openthread shell, and the other optimization options as suggested in https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.0.0/nrf/app_memory.html, but I'm still getting OOMs.

Is there anything I'm missing here?

Kind regards and thanks

-Alex

[Charlie]

Hi Alexander,

Thanks for the feedback about your test.

Have you tested with other platforms(like Apple Homekit, or the Matter development environment mentioned by the NCS document)? 

Did you test with the latest NCS2.1.0? Can you share your modification and complete log file?

Best regards,

Charlie

[abollaert]

Hi Charlie,

sorry for the somewhat late reply, was working on something else the last few days.

I tested using the chiptool and that worked fine, but this test was specifically a test with Google Home.

I tested using the latest NCS (v2.1.0) and I also tested using main (v2.1.99). Results were the same for both (CHIP error 0xb when retrieving data from clusters).

Log file:

Fullscreen 5125.log.txt Download

I: 139425 [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:436199117 on exchange 20695r
I: 139436 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e28
I: 139444 [IN]CASE Server disabling CASE session setups
I: 139450 [IN]Prepared unauthenticated message 0x2002ce70 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 20695r with MessageCounter:231630031.
I: 139465 [IN]Sending unauthenticated msg 0x2002ce70 with MessageCounter:231630031 to 0x0000000000000000 at monotonic time: 00000000000220C9 msec
I: 139479 [SC]Received Sigma1 msg
I: 139487 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000042E141EA
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, c48
I: data wra: 0, a64
*** Booting Zephyr OS build v3.1.99-ncs1-4-g97c4a1a6d1bd  ***
I: Init CHIP stack
I: 226 [DL]BLE address: F4:93:1C:56:5B:06
I: SoftDevice Controller build revision:
I: f2 e7 5f 6f 23 a2 f3 e8 |.._o#...
I: 10 2f c3 35 9e d7 1d fe |./.5....
I: 8f 80 42 f9             |..B.
I: 279 [DL]OpenThread ifconfig up and thread start
I: 286 [DL]OpenThread started: OK
I: 289 [DL]Setting OpenThread device type to ROUTER
I: 294 [SVR]Server initializing...
I: 298 [TS]Last Known Good Time: 2022-09-30T16:51:29
I: 306 [FP]Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x0E9E8F8AAAEC283A, FabricId 0x536743A143EEAC12, NodeId 0x0000000042E141EA, VendorId 0x6006
I: 321 [DMG]AccessControl: initializing
I: 325 [DMG]Examples::AccessControlDelegate::Init
I: 329 [DMG]AccessControl: setting
I: 332 [DMG]DefaultAclStorage: initializing
I: 338 [DMG]DefaultAclStorage: 1 entries loaded
E: 342 [IN]SO_REUSEPORT failed: 109
I: 404 [ZCL]Using ZAP configuration...
I: 440 [DMG]AccessControlCluster: initializing
I: 445 [ZCL]Initiating Admin Commissioning cluster.
I: 450 [ZCL]Window Covering Cluster init
I: 454 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 462 [ZCL]Window Covering Cluster init
I: 466 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 474 [SVR]Fabric already commissioned. Disabling BLE advertisement
I: 480 [DIS]Updating services using commissioning mode 0
I: 485 [DIS]Advertise operational node 0E9E8F8AAAEC283A-0000000042E141EA
E: 492 [DIS]Failed to advertise operational node: 3
I: 497 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 506 [DIS]Failed to advertise extended commissionable node: 3
E: 512 [DIS]Failed to finalize service update: 1c
I: 516 [DIS]Delaying proxy of operational discovery: missing delegate
I: 523 [IN]CASE Server enabling CASE session setups
I: 527 [SVR]Joining Multicast groups
I: 532 [SVR]Server Listening...
I: 534 [DL]Device Configuration:
I: 538 [DL]  Serial Number: 11223344556677889900
I: 543 [DL]  Vendor Id: 65521 (0xFFF1)
I: 546 [DL]  Product Id: 32784 (0x8010)
I: 551 [DL]  Hardware Version: 0
I: 554 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 561 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 568 [DL]  Manufacturing Date: (not set)
I: 572 [DL]  Device Type: 65535 (0xFFFF)
I: 577 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
I: 582 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 588 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
I: 597 [SVR]Manual pairing code: [34970112332]
I: 602 [DL]CHIP task running
I: 625 [ZCL]WC POST ATTRIBUTE=7
I: 627 [ZCL]ConfigStatus 0x1B Operational=1 OnlineReserved=1
I: 633 [ZCL]Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
I: 1174 [DL]SRP Client was started, detected server: fdc5:ac64:3bc5:0000:bea4:88ff:4f45:59a8
I: 1298 [DIS]Setting operational delegate post init
I: 1309 [SWU]Stopping the watchdog timer
I: 1313 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 1319 [DIS]Updating services using commissioning mode 0
I: 1324 [DIS]Advertise operational node 0E9E8F8AAAEC283A-0000000042E141EA
I: 1331 [DL]advertising srp service: 0E9E8F8AAAEC283A-0000000042E141EA._matter._tcp
I: 1340 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
I: 1385 [DL]advertising srp service: FBC63F1B5775F959._matterc._udp
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, fe8
I: data wra: 0, 0
*** Booting Zephyr OS build v3.1.99-ncs1-4-g97c4a1a6d1bd  ***
I: Init CHIP stack
I: 228 [DL]BLE address: CF:CD:F6:85:62:7E
I: SoftDevice Controller build revision:
I: f2 e7 5f 6f 23 a2 f3 e8 |.._o#...
I: 10 2f c3 35 9e d7 1d fe |./.5....
I: 8f 80 42 f9             |..B.
I: 251 [DL]OpenThread started: OK
I: 254 [DL]Setting OpenThread device type to ROUTER
I: 259 [SVR]Server initializing...
I: 262 [TS]Last Known Good Time: [unknown]
I: 266 [TS]Setting Last Known Good Time to firmware build time 2022-09-30T16:51:29
I: 278 [DMG]AccessControl: initializing
I: 281 [DMG]Examples::AccessControlDelegate::Init
I: 286 [DMG]AccessControl: setting
I: 289 [DMG]DefaultAclStorage: initializing
I: 292 [DMG]DefaultAclStorage: 0 entries loaded
E: 297 [IN]SO_REUSEPORT failed: 109
I: 312 [ZCL]Using ZAP configuration...
I: 326 [DMG]AccessControlCluster: initializing
I: 330 [ZCL]Initiating Admin Commissioning cluster.
I: 335 [ZCL]Window Covering Cluster init
I: 343 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 350 [ZCL]Window Covering Cluster init
I: 358 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 367 [DIS]Updating services using commissioning mode 1
I: 373 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 382 [DIS]Failed to advertise commissionable node: 3
E: 386 [DIS]Failed to finalize service update: 1c
I: 391 [DIS]Updating services using commissioning mode 1
I: 397 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 406 [DIS]Failed to advertise commissionable node: 3
E: 411 [DIS]Failed to finalize service update: 1c
I: 415 [DIS]Delaying proxy of operational discovery: missing delegate
I: 421 [IN]CASE Server enabling CASE session setups
I: 426 [SVR]Joining Multicast groups
I: 429 [SVR]Server Listening...
I: 432 [DL]Device Configuration:
I: 435 [DL]  Serial Number: 11223344556677889900
I: 440 [DL]  Vendor Id: 65521 (0xFFF1)
I: 443 [DL]  Product Id: 32784 (0x8010)
I: 447 [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: 462 [DL]  Manufacturing Date: (not set)
I: 466 [DL]  Device Type: 65535 (0xFFFF)
I: 470 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
I: 475 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 481 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
I: 490 [SVR]Manual pairing code: [34970112332]
I: 495 [DL]CHIP task running
I: 500 [DL]CHIPoBLE advertising started
I: 503 [ZCL]WC POST ATTRIBUTE=7
I: 506 [ZCL]ConfigStatus 0x1B Operational=1 OnlineReserved=1
I: 512 [ZCL]Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
I: 518 [DL]NFC Tag emulation started
I: 30503 [DL]CHIPoBLE advertising mode changed to slow
I: 112558 [DL]BLE connection established (ConnId: 0x00)
I: 112563 [DL]Current number of connections: 1/1
I: 112567 [DL]CHIPoBLE advertising stopped
I: 112571 [DL]NFC Tag emulation stopped
I: 113640 [BLE]local and remote recv window sizes = 5
I: 113645 [BLE]selected BTP version 4
I: 113649 [BLE]using BTP fragment sizes rx 128 / tx 128.
I: 113656 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
I: 113730 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:106443299 on exchange 32987r
I: 113742 [IN]Prepared unauthenticated message 0x2002cf28 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 32987r with MessageCounter:251774494.
I: 113756 [IN]Sending unauthenticated msg 0x2002cf28 with MessageCounter:251774494 to 0x0000000000000000 at monotonic time: 000000000001BC5C msec
I: 113911 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:106443300 on exchange 32987r
I: 115780 [IN]Prepared unauthenticated message 0x2002cec0 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 32987r with MessageCounter:251774495.
I: 115795 [IN]Sending unauthenticated msg 0x2002cec0 with MessageCounter:251774495 to 0x0000000000000000 at monotonic time: 000000000001C453 msec
E: 115808 [DL]Long dispatch time: 1898 ms, for event type 16388
I: 115980 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:106443301 on exchange 32987r
I: 115991 [IN]Prepared unauthenticated message 0x2002cf48 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 32987r with MessageCounter:251774496.
I: 116006 [IN]Sending unauthenticated msg 0x2002cf48 with MessageCounter:251774496 to 0x0000000000000000 at monotonic time: 000000000001C525 msec
I: 116019 [SC]SecureSession[0x200034a8]: Moving from state 'kEstablishing' --> 'kActive'
I: 116028 [SVR]Commissioning completed session establishment step
I: 116034 [DIS]Updating services using commissioning mode 0
I: 116040 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 116049 [DIS]Failed to advertise extended commissionable node: 3
E: 116055 [DIS]Failed to finalize service update: 1c
I: 116060 [SVR]Device completed Rendezvous process
I: 117419 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658056 on exchange 32988r
I: 117431 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32988r with MessageCounter:41944965.
I: 117445 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944965 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CAC5 msec
I: 117510 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658057 on exchange 32989r
I: 117522 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32989r with MessageCounter:41944966.
I: 117536 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944966 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CB20 msec
I: 117645 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658058 on exchange 32990r
I: 117660 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32990r with MessageCounter:41944967.
I: 117674 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944967 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CBA9 msec
I: 118273 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658059 on exchange 32991r
I: 118285 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32991r with MessageCounter:41944968.
I: 118299 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944968 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CE1B msec
I: 119893 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:194658060 on exchange 32992r
I: 119903 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (0)  of type 0x1 and protocolId (0, 1) on exchange 32992r with MessageCounter:41944969.
I: 119917 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:41944969 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D46D msec
I: 119984 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658061 on exchange 32992r
I: 119994 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 120001 [IN]Prepared secure message 0x2002cf38 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32992r with MessageCounter:41944970.
I: 120015 [IN]Sending encrypted msg 0x2002cf38 with MessageCounter:41944970 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D4CF msec
I: 120254 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658062 on exchange 32993r
I: 120266 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32993r with MessageCounter:41944971.
I: 120280 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944971 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D5D7 msec
I: 120343 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:194658063 on exchange 32994r
I: 120354 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (0)  of type 0x1 and protocolId (0, 1) on exchange 32994r with MessageCounter:41944972.
I: 120368 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:41944972 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D630 msec
I: 120480 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658064 on exchange 32994r
I: 120500 [IN]Prepared secure message 0x2002cf38 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32994r with MessageCounter:41944973.
I: 120514 [IN]Sending encrypted msg 0x2002cf38 with MessageCounter:41944973 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D6C2 msec
I: 120659 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658065 on exchange 32995r
I: 120669 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 120679 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32995r with MessageCounter:41944974.
I: 120693 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944974 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D774 msec
I: 121603 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658066 on exchange 32996r
I: 121614 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 121623 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32996r with MessageCounter:41944975.
I: 121637 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944975 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DB25 msec
I: 122505 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658067 on exchange 32997r
I: 122515 [ZCL]OpCreds: Received an AttestationRequest command
I: 122551 [ZCL]OpCreds: AttestationRequest successful.
I: 122560 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32997r with MessageCounter:41944976.
I: 122574 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944976 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DECE msec
I: 123450 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658068 on exchange 32998r
I: 123460 [ZCL]OpCreds: Received a CSRRequest command
I: 123651 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 123687 [ZCL]OpCreds: CSRRequest successful.
I: 123694 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 32998r with MessageCounter:41944977.
I: 123708 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944977 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001E33C msec
E: 123721 [DL]Long dispatch time: 272 ms, for event type 16388
I: 125473 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658069 on exchange 32999r
I: 125485 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 32999r with MessageCounter:41944978.
I: 125499 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944978 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001EA3B msec
I: 125836 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658070 on exchange 33000r
I: 125846 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 125910 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 125916 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33000r with MessageCounter:41944979.
I: 125931 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944979 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001EBEA msec
E: 125943 [DL]Long dispatch time: 109 ms, for event type 16388
I: 126692 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658071 on exchange 33001r
I: 126702 [ZCL]OpCreds: Received an AddNOC command
I: 126709 [FP]Validating NOC chain
I: 126827 [FP]NOC chain validation successful
I: 126832 [FP]Added new fabric at index: 0x1
I: 126836 [FP]Assigned compressed fabric ID: 0x0E9E8F8AAAEC283A, node ID: 0x00000000BC2E549C
I: 126844 [TS]Last Known Good Time: 2022-09-30T16:51:29
I: 126849 [TS]New proposed Last Known Good Time: 2022-10-06T07:29:03
I: 126855 [TS]Updating pending Last Known Good Time to 2022-10-06T07:29:03
I: 126886 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
I: 126895 [DIS]Advertise operational node 0E9E8F8AAAEC283A-00000000BC2E549C
I: 126902 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 126910 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33001r with MessageCounter:41944980.
I: 126924 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944980 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001EFCC msec
E: 126937 [DL]Long dispatch time: 248 ms, for event type 16388
I: 127499 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658072 on exchange 33002r
I: 127516 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33002r with MessageCounter:41944981.
I: 127530 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:41944981 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F22A msec
I: 127948 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:194658073 on exchange 33003r
I: 127960 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (1)  of type 0x5 and protocolId (0, 1) on exchange 33003r with MessageCounter:41944982.
I: 127974 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:41944982 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F3E6 msec
I: 128128 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:194658074 on exchange 33004r
I: 128139 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (1)  of type 0x1 and protocolId (0, 1) on exchange 33004r with MessageCounter:41944983.
I: 128153 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:41944983 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F499 msec
I: 128219 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:194658075 on exchange 33004r
I: 128666 [DL]BLE GAP connection terminated (reason 0x08)
I: 128671 [BLE]Releasing end point's BLE connection back to application.
I: 128678 [DL]Closing BLE GATT connection (ConnId 00)
I: 128683 [DL]Current number of connections: 0/1
I: 129569 [DL]SRP Client was started, detected server: fdc5:ac64:3bc5:0000:bea4:88ff:4f45:59a8
E: 129832 [DL]Long dispatch time: 254 ms, for event type 3
I: 129840 [IN]Prepared secure message 0x2002d188 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33004r with MessageCounter:41944984.
I: 129857 [IN]Sending encrypted msg 0x2002d188 with MessageCounter:41944984 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001FB41 msec
I: 129871 [DIS]Advertise operational node 0E9E8F8AAAEC283A-00000000BC2E549C
I: 129879 [SVR]Operational advertising enabled
I: 129901 [DIS]Setting operational delegate post init
I: 129909 [SWU]Stopping the watchdog timer
I: 129913 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 129919 [DIS]Updating services using commissioning mode 0
I: 129925 [DIS]Advertise operational node 0E9E8F8AAAEC283A-00000000BC2E549C
I: 129932 [DL]advertising srp service: 0E9E8F8AAAEC283A-00000000BC2E549C._matter._tcp
I: 129940 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
I: 129987 [DL]advertising srp service: 47BB1B010D9232A8._matterc._udp
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, fe8
I: data wra: 0, 0
*** Booting Zephyr OS build v3.1.99-ncs1-4-g97c4a1a6d1bd  ***
I: Init CHIP stack
I: 228 [DL]BLE address: DA:D8:45:F1:A0:7C
I: SoftDevice Controller build revision:
I: f2 e7 5f 6f 23 a2 f3 e8 |.._o#...
I: 10 2f c3 35 9e d7 1d fe |./.5....
I: 8f 80 42 f9             |..B.
I: 251 [DL]OpenThread started: OK
I: 254 [DL]Setting OpenThread device type to ROUTER
I: 259 [SVR]Server initializing...
I: 262 [TS]Last Known Good Time: [unknown]
I: 266 [TS]Setting Last Known Good Time to firmware build time 2022-09-30T16:51:29
I: 277 [DMG]AccessControl: initializing
I: 281 [DMG]Examples::AccessControlDelegate::Init
I: 285 [DMG]AccessControl: setting
I: 288 [DMG]DefaultAclStorage: initializing
I: 292 [DMG]DefaultAclStorage: 0 entries loaded
E: 297 [IN]SO_REUSEPORT failed: 109
I: 312 [ZCL]Using ZAP configuration...
I: 325 [DMG]AccessControlCluster: initializing
I: 330 [ZCL]Initiating Admin Commissioning cluster.
I: 334 [ZCL]Window Covering Cluster init
I: 343 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 350 [ZCL]Window Covering Cluster init
I: 358 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 367 [DIS]Updating services using commissioning mode 1
I: 372 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 381 [DIS]Failed to advertise commissionable node: 3
E: 386 [DIS]Failed to finalize service update: 1c
I: 391 [DIS]Updating services using commissioning mode 1
I: 396 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 406 [DIS]Failed to advertise commissionable node: 3
E: 410 [DIS]Failed to finalize service update: 1c
I: 415 [DIS]Delaying proxy of operational discovery: missing delegate
I: 421 [IN]CASE Server enabling CASE session setups
I: 426 [SVR]Joining Multicast groups
I: 429 [SVR]Server Listening...
I: 432 [DL]Device Configuration:
I: 435 [DL]  Serial Number: 11223344556677889900
I: 440 [DL]  Vendor Id: 65521 (0xFFF1)
I: 443 [DL]  Product Id: 32784 (0x8010)
I: 447 [DL]  Hardware Version: 0
I: 450 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 455 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 462 [DL]  Manufacturing Date: (not set)
I: 466 [DL]  Device Type: 65535 (0xFFFF)
I: 470 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
I: 475 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 481 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
I: 490 [SVR]Manual pairing code: [34970112332]
I: 495 [DL]CHIP task running
I: 499 [DL]CHIPoBLE advertising started
I: 503 [ZCL]WC POST ATTRIBUTE=7
I: 506 [ZCL]ConfigStatus 0x1B Operational=1 OnlineReserved=1
I: 512 [ZCL]Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
I: 518 [DL]NFC Tag emulation started
I: 30503 [DL]CHIPoBLE advertising mode changed to slow
I: 116062 [DL]BLE connection established (ConnId: 0x00)
I: 116067 [DL]Current number of connections: 1/1
I: 116071 [DL]CHIPoBLE advertising stopped
I: 116075 [DL]NFC Tag emulation stopped
I: 117709 [BLE]local and remote recv window sizes = 5
I: 117714 [BLE]selected BTP version 4
I: 117718 [BLE]using BTP fragment sizes rx 128 / tx 128.
I: 117725 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
I: 117777 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:106443302 on exchange 33005r
I: 117788 [IN]Prepared unauthenticated message 0x2002cf28 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 33005r with MessageCounter:107173456.
I: 117803 [IN]Sending unauthenticated msg 0x2002cf28 with MessageCounter:107173456 to 0x0000000000000000 at monotonic time: 000000000001CC2B msec
I: 118047 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:106443303 on exchange 33005r
I: 119917 [IN]Prepared unauthenticated message 0x2002cec0 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 33005r with MessageCounter:107173457.
I: 119932 [IN]Sending unauthenticated msg 0x2002cec0 with MessageCounter:107173457 to 0x0000000000000000 at monotonic time: 000000000001D47C msec
E: 119945 [DL]Long dispatch time: 1898 ms, for event type 16388
I: 120116 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:106443304 on exchange 33005r
I: 120127 [IN]Prepared unauthenticated message 0x2002cf48 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 33005r with MessageCounter:107173458.
I: 120142 [IN]Sending unauthenticated msg 0x2002cf48 with MessageCounter:107173458 to 0x0000000000000000 at monotonic time: 000000000001D54E msec
I: 120156 [SC]SecureSession[0x200034a8]: Moving from state 'kEstablishing' --> 'kActive'
I: 120164 [SVR]Commissioning completed session establishment step
I: 120170 [DIS]Updating services using commissioning mode 0
I: 120176 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 120186 [DIS]Failed to advertise extended commissionable node: 3
E: 120192 [DIS]Failed to finalize service update: 1c
I: 120196 [SVR]Device completed Rendezvous process
I: 120296 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576463 on exchange 33006r
I: 120308 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33006r with MessageCounter:267478342.
I: 120322 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478342 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D602 msec
I: 120387 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576464 on exchange 33007r
I: 120399 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33007r with MessageCounter:267478343.
I: 120413 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478343 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D65C msec
I: 120567 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576465 on exchange 33008r
I: 120581 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33008r with MessageCounter:267478344.
I: 120595 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478344 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D713 msec
I: 121061 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576466 on exchange 33009r
I: 121073 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33009r with MessageCounter:267478345.
I: 121087 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478345 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001D8FF msec
I: 121824 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:42576467 on exchange 33010r
I: 121835 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (0)  of type 0x1 and protocolId (0, 1) on exchange 33010r with MessageCounter:267478346.
I: 121849 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:267478346 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DBF9 msec
I: 121916 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576468 on exchange 33010r
I: 121926 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 121933 [IN]Prepared secure message 0x2002cf38 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33010r with MessageCounter:267478347.
I: 121947 [IN]Sending encrypted msg 0x2002cf38 with MessageCounter:267478347 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DC5B msec
I: 122141 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576469 on exchange 33011r
I: 122152 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33011r with MessageCounter:267478348.
I: 122166 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478348 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DD36 msec
I: 122230 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:42576470 on exchange 33012r
I: 122241 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (0)  of type 0x1 and protocolId (0, 1) on exchange 33012r with MessageCounter:267478349.
I: 122255 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:267478349 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DD8E msec
I: 122321 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576471 on exchange 33012r
I: 122342 [IN]Prepared secure message 0x2002cf38 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33012r with MessageCounter:267478350.
I: 122356 [IN]Sending encrypted msg 0x2002cf38 with MessageCounter:267478350 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DDF4 msec
I: 122456 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576472 on exchange 33013r
I: 122466 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 122475 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33013r with MessageCounter:267478351.
I: 122489 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478351 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001DE79 msec
I: 123086 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576473 on exchange 33014r
I: 123096 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 123105 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33014r with MessageCounter:267478352.
I: 123119 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478352 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001E0EF msec
I: 123672 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576474 on exchange 33015r
I: 123682 [ZCL]OpCreds: Received an AttestationRequest command
I: 123718 [ZCL]OpCreds: AttestationRequest successful.
I: 123727 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33015r with MessageCounter:267478353.
I: 123741 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478353 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001E35D msec
I: 124347 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576475 on exchange 33016r
I: 124357 [ZCL]OpCreds: Received a CSRRequest command
I: 124548 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 124584 [ZCL]OpCreds: CSRRequest successful.
I: 124590 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33016r with MessageCounter:267478354.
I: 124604 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478354 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001E6BC msec
E: 124617 [DL]Long dispatch time: 271 ms, for event type 16388
I: 126190 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576476 on exchange 33017r
I: 126202 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 33017r with MessageCounter:267478355.
I: 126216 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478355 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001ED08 msec
I: 126598 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576477 on exchange 33018r
I: 126608 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 126671 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 126678 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 33018r with MessageCounter:267478356.
I: 126693 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478356 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001EEE4 msec
E: 126705 [DL]Long dispatch time: 109 ms, for event type 16388
I: 127453 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576478 on exchange 33019r
I: 127463 [ZCL]OpCreds: Received an AddNOC command
I: 127470 [FP]Validating NOC chain
I: 127589 [FP]NOC chain validation successful
I: 127593 [FP]Added new fabric at index: 0x1
I: 127597 [FP]Assigned compressed fabric ID: 0x0E9E8F8AAAEC283A, node ID: 0x000000006CA6166E
I: 127605 [TS]Last Known Good Time: 2022-09-30T16:51:29
I: 127610 [TS]New proposed Last Known Good Time: 2022-10-06T07:32:12
I: 127616 [TS]Updating pending Last Known Good Time to 2022-10-06T07:32:12
I: 127648 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
I: 127657 [DIS]Advertise operational node 0E9E8F8AAAEC283A-000000006CA6166E
I: 127664 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 127671 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33019r with MessageCounter:267478357.
I: 127686 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478357 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F2C5 msec
E: 127699 [DL]Long dispatch time: 250 ms, for event type 16388
I: 128080 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576479 on exchange 33020r
I: 128098 [IN]Prepared secure message 0x2002cfa0 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33020r with MessageCounter:267478358.
I: 128112 [IN]Sending encrypted msg 0x2002cfa0 with MessageCounter:267478358 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F46F msec
I: 128260 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:42576480 on exchange 33021r
I: 128272 [IN]Prepared secure message 0x2002d0d0 to 0xFFFFFFFB00000000 (1)  of type 0x5 and protocolId (0, 1) on exchange 33021r with MessageCounter:267478359.
I: 128286 [IN]Sending encrypted msg 0x2002d0d0 with MessageCounter:267478359 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F51D msec
I: 128350 [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:42576481 on exchange 33022r
I: 128360 [IN]Prepared secure message 0x2002ced0 to 0xFFFFFFFB00000000 (1)  of type 0x1 and protocolId (0, 1) on exchange 33022r with MessageCounter:267478360.
I: 128375 [IN]Sending encrypted msg 0x2002ced0 with MessageCounter:267478360 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001F576 msec
I: 128441 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:42576482 on exchange 33022r
I: 129997 [DL]SRP Client was started, detected server: fdc5:ac64:3bc5:0000:bea4:88ff:4f45:59a8
E: 130249 [DL]Long dispatch time: 243 ms, for event type 3
I: 130256 [IN]Prepared secure message 0x2002d188 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 33022r with MessageCounter:267478361.
I: 130273 [IN]Sending encrypted msg 0x2002d188 with MessageCounter:267478361 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001FCE1 msec
I: 130288 [DIS]Advertise operational node 0E9E8F8AAAEC283A-000000006CA6166E
I: 130296 [SVR]Operational advertising enabled
I: 130384 [DIS]Setting operational delegate post init
I: 130392 [SWU]Stopping the watchdog timer
I: 130396 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 130403 [DIS]Updating services using commissioning mode 0
I: 130409 [DIS]Advertise operational node 0E9E8F8AAAEC283A-000000006CA6166E
I: 130416 [DL]advertising srp service: 0E9E8F8AAAEC283A-000000006CA6166E._matter._tcp
I: 130425 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
I: 130470 [DL]advertising srp service: FEF5AD8261517BA8._matterc._udp
I: 133685 [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:106443305 on exchange 33023r
I: 133695 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e28
I: 133703 [IN]CASE Server disabling CASE session setups
I: 133708 [IN]Prepared unauthenticated message 0x2002ce70 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 33023r with MessageCounter:107173459.
I: 133723 [IN]Sending unauthenticated msg 0x2002ce70 with MessageCounter:107173459 to 0x0000000000000000 at monotonic time: 0000000000020A5B msec
I: 133737 [SC]Received Sigma1 msg
I: 133744 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x000000006CA6166E
I: 133968 [IN]Prepared unauthenticated message 0x200050dc to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 33023r with MessageCounter:107173460.
I: 133984 [IN]Sending unauthenticated msg 0x200050dc with MessageCounter:107173460 to 0x0000000000000000 at monotonic time: 0000000000020B5F msec
I: 133998 [SC]Sent Sigma2 msg
I: 134186 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:106443306 on exchange 33023r
I: 134305 [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:106443307 on exchange 33023r
I: 134315 [IN]Prepared unauthenticated message 0x2002ce60 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 33023r with MessageCounter:107173461.
I: 134330 [IN]Sending unauthenticated msg 0x2002ce60 with MessageCounter:107173461 to 0x0000000000000000 at monotonic time: 0000000000020CBA msec
I: 134344 [SC]Received Sigma3 msg
E: 134353 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
I: 134728 [IN]Prepared unauthenticated message 0x200050dc to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 33023r with MessageCounter:107173462.
I: 134743 [IN]Sending unauthenticated msg 0x200050dc with MessageCounter:107173462 to 0x0000000000000000 at monotonic time: 0000000000020E57 msec
I: 134758 [SC]SecureSession[0x20003560]: Moving from state 'kEstablishing' --> 'kActive'
I: 134766 [IN]CASE Session established to peer: <000000002392C82F, 1>
I: 134773 [IN]CASE Server enabling CASE session setups
I: 134883 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:106443308 on exchange 33023r
I: 134896 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145253 on exchange 33024r
I: 134908 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33024r with MessageCounter:1259316.
I: 134922 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259316 to 0x000000002392C82F (1) at monotonic time: 0000000000020F0A msec
I: 135014 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145254 on exchange 33024r
I: 135027 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145255 on exchange 33025r
I: 135039 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33025r with MessageCounter:1259317.
I: 135053 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259317 to 0x000000002392C82F (1) at monotonic time: 0000000000020F8D msec
I: 135096 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145256 on exchange 33025r
I: 135108 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145257 on exchange 33026r
I: 135123 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33026r with MessageCounter:1259318.
I: 135137 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259318 to 0x000000002392C82F (1) at monotonic time: 0000000000020FE1 msec
I: 135254 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145258 on exchange 33026r
I: 135267 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145259 on exchange 33027r
I: 135279 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33027r with MessageCounter:1259319.
I: 135293 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259319 to 0x000000002392C82F (1) at monotonic time: 000000000002107D msec
I: 135378 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145260 on exchange 33027r
I: 135391 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145261 on exchange 33028r
I: 135403 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33028r with MessageCounter:1259320.
I: 135417 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259320 to 0x000000002392C82F (1) at monotonic time: 00000000000210F9 msec
I: 135504 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145262 on exchange 33028r
I: 135516 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145263 on exchange 33029r
I: 135528 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33029r with MessageCounter:1259321.
I: 135542 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259321 to 0x000000002392C82F (1) at monotonic time: 0000000000021176 msec
I: 135634 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145264 on exchange 33029r
I: 135651 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145265 on exchange 33030r
I: 135663 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33030r with MessageCounter:1259322.
I: 135677 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259322 to 0x000000002392C82F (1) at monotonic time: 00000000000211FD msec
I: 135767 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145266 on exchange 33030r
I: 135793 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145267 on exchange 33031r
I: 135805 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33031r with MessageCounter:1259323.
I: 135819 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259323 to 0x000000002392C82F (1) at monotonic time: 000000000002128B msec
I: 135897 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145268 on exchange 33031r
I: 135910 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145269 on exchange 33032r
I: 135922 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33032r with MessageCounter:1259324.
I: 135936 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259324 to 0x000000002392C82F (1) at monotonic time: 0000000000021300 msec
I: 136041 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145270 on exchange 33032r
I: 136054 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145271 on exchange 33033r
I: 136066 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33033r with MessageCounter:1259325.
I: 136080 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259325 to 0x000000002392C82F (1) at monotonic time: 000000000002138F msec
I: 136121 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145272 on exchange 33033r
I: 136134 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145273 on exchange 33034r
I: 136146 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33034r with MessageCounter:1259326.
I: 136160 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259326 to 0x000000002392C82F (1) at monotonic time: 00000000000213E0 msec
I: 136209 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145274 on exchange 33034r
I: 136223 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:198145275 on exchange 33035r
I: 136234 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x5 and protocolId (0, 1) on exchange 33035r with MessageCounter:1259327.
I: 136248 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259327 to 0x000000002392C82F (1) at monotonic time: 0000000000021438 msec
I: 136294 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145276 on exchange 33035r
I: 141341 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:198145277 on exchange 33036r
I: 141351 [FS]GeneralCommissioning: Received CommissioningComplete
I: 141478 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 141748 [TS]Committing Last Known Good Time to storage: 2022-10-06T07:32:12
I: 141837 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x0E9E8F8AAAEC283A, FabricId 536743A143EEAC12, NodeId 000000006CA6166E, VendorId 0x6006
I: 141874 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 141881 [FS]Fail-safe cleanly disarmed
I: 141886 [IN]Prepared secure message 0x200050dc to 0x000000002392C82F (1)  of type 0x9 and protocolId (0, 1) on exchange 33036r with MessageCounter:1259328.
I: 141900 [IN]Sending encrypted msg 0x200050dc with MessageCounter:1259328 to 0x000000002392C82F (1) at monotonic time: 0000000000022A4C msec
I: 141914 [SWU]Device commissioned, schedule a default provider query
I: 141920 [SVR]Commissioning completed successfully
I: 141925 [DIS]Updating services using commissioning mode 0
I: 141931 [DIS]Advertise operational node 0E9E8F8AAAEC283A-000000006CA6166E
I: 141939 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
I: 141949 [SC]SecureSession[0x200034a8]: Moving from state 'kActive' --> 'kPendingEviction'
I: 141957 [BLE]Releasing end point's BLE connection back to application.
I: 141963 [DL]Closing BLE GATT connection (ConnId 00)
I: 142027 [DL]BLE GAP connection terminated (reason 0x16)
I: 142033 [DL]Current number of connections: 0/1
I: 142039 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:198145278 on exchange 33036r
I: 143280 [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:3661630385 on exchange 54120r
I: 143291 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e28
I: 143298 [IN]CASE Server disabling CASE session setups
I: 143303 [IN]Prepared unauthenticated message 0x2002ce70 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 54120r with MessageCounter:107173463.
I: 143318 [IN]Sending unauthenticated msg 0x2002ce70 with MessageCounter:107173463 to 0x0000000000000000 at monotonic time: 0000000000022FD6 msec
I: 143332 [SC]Received Sigma1 msg
I: 143340 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x000000006CA6166E
I: 143562 [IN]Prepared unauthenticated message 0x200050dc to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 54120r with MessageCounter:107173464.
I: 143577 [IN]Sending unauthenticated msg 0x200050dc with MessageCounter:107173464 to 0x0000000000000000 at monotonic time: 00000000000230D9 msec
I: 143591 [SC]Sent Sigma2 msg
I: 143790 [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3661630386 on exchange 54120r
I: 143801 [IN]Prepared unauthenticated message 0x2002ce60 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 54120r with MessageCounter:107173465.
I: 143816 [IN]Sending unauthenticated msg 0x2002ce60 with MessageCounter:107173465 to 0x0000000000000000 at monotonic time: 00000000000231C8 msec
I: 143830 [SC]Received Sigma3 msg
E: 143838 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
I: 144136 [IN]Prepared unauthenticated message 0x200050dc to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 54120r with MessageCounter:107173466.
I: 144151 [IN]Sending unauthenticated msg 0x200050dc with MessageCounter:107173466 to 0x0000000000000000 at monotonic time: 0000000000023317 msec
I: 144166 [SC]SecureSession[0x20003618]: Moving from state 'kEstablishing' --> 'kActive'
I: 144174 [IN]CASE Session established to peer: <0000000056E421FF, 1>
I: 144180 [IN]CASE Server enabling CASE session setups
I: 144188 [EM]Received message of type 0x3 with protocolId (0, 1) and MessageCounter:15066513 on exchange 54121r
I: 144200 [DMG]Final negotiated min/max parameters: Min = 0s, Max = 120s
E: 144209 [DMG]Error retrieving data from clusterId: 0x0000_001D, err = b
I: 144221 [IN]Prepared secure message 0x200050f4 to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971247.
I: 144235 [IN]Sending encrypted msg 0x200050f4 with MessageCounter:249971247 to 0x0000000056E421FF (1) at monotonic time: 000000000002336B msec
I: 144250 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3661630387 on exchange 54120r
I: 144335 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066514 on exchange 54121r
I: 144345 [IM]Received status response, status is 0x00
E: 144355 [DMG]Error retrieving data from clusterId: 0x0000_0028, err = b
I: 144367 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971248.
I: 144381 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971248 to 0x0000000056E421FF (1) at monotonic time: 00000000000233FD msec
I: 144483 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066515 on exchange 54121r
I: 144493 [IM]Received status response, status is 0x00
E: 144503 [DMG]Error retrieving data from clusterId: 0x0000_0028, err = b
I: 144515 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971249.
I: 144529 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971249 to 0x0000000056E421FF (1) at monotonic time: 0000000000023491 msec
I: 144637 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066516 on exchange 54121r
I: 144647 [IM]Received status response, status is 0x00
E: 144655 [DMG]Error retrieving data from clusterId: 0x0000_002F, err = b
I: 144667 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971250.
I: 144681 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971250 to 0x0000000056E421FF (1) at monotonic time: 0000000000023529 msec
I: 144784 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066517 on exchange 54121r
I: 144794 [IM]Received status response, status is 0x00
E: 144801 [DMG]Error retrieving data from clusterId: 0x0000_0030, err = b
I: 144813 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971251.
I: 144827 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971251 to 0x0000000056E421FF (1) at monotonic time: 00000000000235BB msec
I: 144933 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066518 on exchange 54121r
I: 144943 [IM]Received status response, status is 0x00
E: 144952 [DMG]Error retrieving data from clusterId: 0x0000_0031, err = b
I: 144964 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971252.
I: 144978 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971252 to 0x0000000056E421FF (1) at monotonic time: 0000000000023652 msec
I: 145081 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066519 on exchange 54121r
I: 145091 [IM]Received status response, status is 0x00
E: 145100 [DMG]Error retrieving data from clusterId: 0x0000_0033, err = b
I: 145112 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971253.
I: 145126 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971253 to 0x0000000056E421FF (1) at monotonic time: 00000000000236E6 msec
I: 145233 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066520 on exchange 54121r
I: 145243 [IM]Received status response, status is 0x00
E: 145251 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
E: 145259 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 145271 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971254.
I: 145285 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971254 to 0x0000000056E421FF (1) at monotonic time: 0000000000023784 msec
I: 145387 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066521 on exchange 54121r
I: 145397 [IM]Received status response, status is 0x00
E: 145407 [DL]_WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
E: 145415 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 145427 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971255.
I: 145441 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971255 to 0x0000000056E421FF (1) at monotonic time: 0000000000023821 msec
I: 145552 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066522 on exchange 54121r
I: 145562 [IM]Received status response, status is 0x00
E: 145578 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 145589 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971256.
I: 145603 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971256 to 0x0000000056E421FF (1) at monotonic time: 00000000000238C3 msec
I: 145704 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066523 on exchange 54121r
I: 145714 [IM]Received status response, status is 0x00
E: 145721 [DMG]Error retrieving data from clusterId: 0x0000_0035, err = b
I: 145732 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971257.
I: 145746 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971257 to 0x0000000056E421FF (1) at monotonic time: 0000000000023952 msec
I: 145857 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066524 on exchange 54121r
I: 145867 [IM]Received status response, status is 0x00
E: 145874 [DMG]Error retrieving data from clusterId: 0x0000_003C, err = b
I: 145885 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971258.
I: 145900 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971258 to 0x0000000056E421FF (1) at monotonic time: 00000000000239EB msec
I: 146000 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066525 on exchange 54121r
I: 146010 [IM]Received status response, status is 0x00
E: 146017 [DMG]Error retrieving data from clusterId: 0x0000_003E, err = b
I: 146028 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971259.
I: 146043 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971259 to 0x0000000056E421FF (1) at monotonic time: 0000000000023A7A msec
I: 146156 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066526 on exchange 54121r
I: 146166 [IM]Received status response, status is 0x00
E: 146172 [DMG]Error retrieving data from clusterId: 0x0000_003E, err = b
I: 146184 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971260.
I: 146198 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971260 to 0x0000000056E421FF (1) at monotonic time: 0000000000023B16 msec
I: 146299 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066527 on exchange 54121r
I: 146309 [IM]Received status response, status is 0x00
E: 146318 [DMG]Error retrieving data from clusterId: 0x0000_003F, err = b
I: 146329 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971261.
I: 146344 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971261 to 0x0000000056E421FF (1) at monotonic time: 0000000000023BA7 msec
I: 146446 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066528 on exchange 54121r
I: 146456 [IM]Received status response, status is 0x00
E: 146464 [DMG]Error retrieving data from clusterId: 0x0000_0003, err = b
I: 146476 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971262.
I: 146490 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971262 to 0x0000000056E421FF (1) at monotonic time: 0000000000023C3A msec
I: 146601 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066529 on exchange 54121r
I: 146611 [IM]Received status response, status is 0x00
E: 146618 [DMG]Error retrieving data from clusterId: 0x0000_0102, err = b
I: 146630 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971263.
I: 146644 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971263 to 0x0000000056E421FF (1) at monotonic time: 0000000000023CD4 msec
I: 146747 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066530 on exchange 54121r
I: 146757 [IM]Received status response, status is 0x00
E: 146764 [DMG]Error retrieving data from clusterId: 0x0000_0102, err = b
I: 146776 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971264.
I: 146790 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971264 to 0x0000000056E421FF (1) at monotonic time: 0000000000023D66 msec
I: 146896 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066531 on exchange 54121r
I: 146906 [IM]Received status response, status is 0x00
E: 146913 [DMG]Error retrieving data from clusterId: 0x0000_001D, err = b
I: 146925 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971265.
I: 146939 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971265 to 0x0000000056E421FF (1) at monotonic time: 0000000000023DFB msec
I: 147040 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066532 on exchange 54121r
I: 147050 [IM]Received status response, status is 0x00
E: 147059 [DMG]Error retrieving data from clusterId: 0x0000_0102, err = b
I: 147070 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971266.
I: 147084 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971266 to 0x0000000056E421FF (1) at monotonic time: 0000000000023E8C msec
I: 147193 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066533 on exchange 54121r
I: 147203 [IM]Received status response, status is 0x00
I: 147214 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x5 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971267.
I: 147228 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971267 to 0x0000000056E421FF (1) at monotonic time: 0000000000023F1C msec
I: 147331 [EM]Received message of type 0x1 with protocolId (0, 1) and MessageCounter:15066534 on exchange 54121r
I: 147341 [IM]Received status response, status is 0x00
I: 147346 [DMG]Refresh Subscribe Sync Timer with max 120 seconds
I: 147352 [IN]Prepared secure message 0x200050dc to 0x0000000056E421FF (1)  of type 0x4 and protocolId (0, 1) on exchange 54121r with MessageCounter:249971268.
I: 147367 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971268 to 0x0000000056E421FF (1) at monotonic time: 0000000000023FA6 msec
I: 147715 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971268 to 0x0000000056E421FF (1) at monotonic time: 0000000000024103 msec
I: 147729 [DIS]Resolving 0E9E8F8AAAEC283A:0000000056E421FF ...
I: 147930 [DIS]Checking node lookup status after 200 ms
I: 148071 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971268 to 0x0000000056E421FF (1) at monotonic time: 0000000000024267 msec
I: 148725 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971268 to 0x0000000056E421FF (1) at monotonic time: 00000000000244F5 msec
I: 149776 [IN]Sending encrypted msg 0x200050dc with MessageCounter:249971268 to 0x0000000056E421FF (1) at monotonic time: 0000000000024910 msec
E: 151298 [EM]Failed to Send CHIP MessageCounter:249971268 on exchange 54121r sendCount: 4 max retries: 4
I: 151308 [SC]SecureSession[0x20003618]: Moving from state 'kActive' --> 'kDefunct'
I: 162730 [DIS]Checking node lookup status after 15000 ms
E: 162735 [DIS]OperationalSessionSetup[1:0000000056E421FF]: operational discovery failed: 32
E: 171920 [SWU]No suitable OTA Provider candidate found
I: 171925 [SWU]No provider available
I: 267381 [DMG]Refresh subscribe timer sync after 120 seconds
E: 267391 [EM]NewContext failed: session inactive
E: 267396 [-]exchange != nullptr:209 false: 3
E: 267400 [DMG]<RE> Error sending out report data with 3!

Project configuration:

# General.
CONFIG_STD_CPP14=y
CONFIG_DK_LIBRARY=y
CONFIG_PWM=y

# OpenThread.
CONFIG_OPENTHREAD_PANID=4660
CONFIG_OPENTHREAD_CHANNEL=15
CONFIG_OPENTHREAD_NETWORK_NAME="OpenThread"
CONFIG_OPENTHREAD_XPANID="00:11:22:33:44:55:66:77"

# Bluetooth overrides
CONFIG_BT_DEVICE_NAME="MatterPOC"

# CHIP configuration
CONFIG_CHIP=y
CONFIG_CHIP_PROJECT_CONFIG="src/main/include/CHIPProjectConfig.h"
CONFIG_CHIP_DEVICE_PRODUCT_ID=32784

# Enable CHIP pairing automatically on application start.
CONFIG_CHIP_ENABLE_PAIRING_AUTOSTART=y

# Disable various debug options to reduce footprint.
CONFIG_SHELL=n
CONFIG_LOG_MODE_IMMEDIATE=n
CONFIG_LOG_MODE_MINIMAL=y
CONFIG_ASSERT_VERBOSE=n
CONFIG_ASSERT_NO_FILE_INFO=y
CONFIG_PRINTK=n
CONFIG_PRINTK_SYNC=n
CONFIG_THREAD_NAME=n
CONFIG_MATTER_LOG_LEVEL_INF=y

Kind regards and thanks,

-Alexander

[abollaert]

I also did another test, this time using the light bulb sample, and I get the same issue. In fact the only sample I ever got working with Google Home is the one the Google developer guide points to (https://developers.home.google.com/matter/vendors/nordic-semiconductor).

Both samples I've tried included in the NCS itself seem to fail with CHIP error 0xb, for example this is the lighting app sample:

log-lighting.txt

It first states it's "Generating Reports", and then you get an 0x0b.

So there must be some difference between the sample the Google development guide points to, and the (more recent) NCS samples, perhaps just a version difference, don't know.

Kind regards,

-Alex

[abollaert]

Did a bit more digging, and I don't think the memory error is the cause for the commissioning failure.

The commissioning succeeds (in that it gets added to my devices in google home), but interaction with the device always fails with an error "operation discovery failed: 32". In Google Home the device gets marked as "unavailable".

D: 119459 [CSM]UpdatePeerAddress: No existing OperationalSessionSetup instance found 
D: 119467 [CTL]OperationalSessionSetup[1:0000000056E421FF]: State change 1 --> 2 
I: 119475 [DIS]Resolving 0E9E8F8AAAEC283A:0000000056E421FF ... 
I: 119675 [DIS]Checking node lookup status after 201 ms 
D: 119819 [EM]Retransmitting MessageCounter:107169467 on exchange 8696r Send Cnt 2 
I: 119827 [IN]Sending encrypted msg 0x20005134 with MessageCounter:107169467 to 0x0000000056E421FF (1) at monotonic time: 000000000001D412 msec 
D: 120474 [EM]Retransmitting MessageCounter:107169467 on exchange 8696r Send Cnt 3 
I: 120481 [IN]Sending encrypted msg 0x20005134 with MessageCounter:107169467 to 0x0000000056E421FF (1) at monotonic time: 000000000001D6A1 msec 
D: 121500 [EM]Retransmitting MessageCounter:107169467 on exchange 8696r Send Cnt 4 
I: 121508 [IN]Sending encrypted msg 0x20005134 with MessageCounter:107169467 to 0x0000000056E421FF (1) at monotonic time: 000000000001DAA3 msec 
E: 123124 [EM]Failed to Send CHIP MessageCounter:107169467 on exchange 8696r sendCount: 4 max retries: 4 
D: 123133 [IN]SecureSession[0x20003670]: MarkAsDefunct Type:2 LSID:7749 
I: 123139 [SC]SecureSession[0x20003670]: Moving from state 'kActive' --> 'kDefunct' 
I: 134475 [DIS]Checking node lookup status after 15001 ms 
E: 134480 [DIS]OperationalSessionSetup[1:0000000056E421FF]: operational discovery failed: 32
 

For reference, my setup is an nRF52840 devkit for the sample, a Google Nest Hub 2 as the border router, commissioner and controller.

Kind regards,

-Alex

[Charlie]

Hi Alex,

I will check with our development team to see if they can repeat this issue with Google Nest Hub 2.

Thanks for reporting this issue to us.

Best regards,

Charlie