Matter v2.2.0 unable to android commission, with "pairing failed"

[Jacob]

Ive been trying the last few Sdk versions to evaluate the matter examples without luck. With 2.2 released yesterday I jumped on that hoping it would clear up my issue, but no dice.

22.04 ubuntu with nrf-docker with v2.2.0, programmed the rcp and the matter light bulb example
rpi 3b+ setup like the 2.2 docs say ot-br-posix @ 0895ad5
I have the android chiptool associated with the 2.2 tag

Im unable to commission ble over thread, with "pairing failed" in android chiptool

My logs on the nrf52840 dk get to here before "I: 137257 [FS]Fail-safe timer expired"

D: 110318 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 110324 [DL]OpenThread State Changed (Flags: 0x1006c100)
D: 110330 [DL] Network Name: OpenThread
D: 110333 [DL] PAN Id: 0x46A7
D: 110336 [DL] Extended PAN Id: 0x0747C2C1E3CB1D09
D: 110341 [DL] Channel: 16
D: 110344 [DL] Mesh Prefix: fdde:ad00:beef::/64
D: 110348 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 110354 [DL] Device Role: DETACHED
D: 110358 [DL] Thread Unicast Addresses:
D: 110362 [DL] fdde:ad00:beef:0:a3c1:30d8:5d26:74f3/64 valid
D: 110368 [DL] fe80::94f5:b84b:42a5:9b84/64 valid preferred
D: 112781 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 112875 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 115350 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 117858 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 117915 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 120390 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 122898 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 122956 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

My logs on the pi are verbose, but something that stands out, but doesnt google anywhere else is a "Failed to process Child ID Request: Security"

Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.813 [W] Mle-----------: Failed to process Child ID Request: Security
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.953 [I] Mac-----------: Frame tx attempt 16/16 failed, error:NoAck, len:126, seqnum:31, type:Data, src:6ae4f275a2ab4472, dst:beada8f9f39cdb0a, sec:yes, ackreq:yes
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.953 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:313, chksum:62da, ecn:no, to:beada8f9f39cdb0a, sec:yes, error:NoAck, prio:net
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.953 [N] MeshForwarder-: src:[fe80:0:0:0:68e4:f275:a2ab:4472]:19788
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.953 [N] MeshForwarder-: dst:[fe80:0:0:0:bcad:a8f9:f39c:db0a]:19788
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.992 [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:bcb5, ecn:no, from:beada8f9f39cdb0a, sec:no, prio:net, rss:-69.0
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.992 [I] MeshForwarder-: src:[fe80:0:0:0:bcad:a8f9:f39c:db0a]:19788
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.992 [I] MeshForwarder-: dst:[fe80:0:0:0:68e4:f275:a2ab:4472]:19788
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:33.992 [W] Mle-----------: Failed to process UDP: Duplicated
Dec 08 01:02:47 raspberrypi otbr-agent[27385]: 05:29:34.036 [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:bcb5, ecn:no, from:beada8f9f39cdb0a, sec:no, prio:net, rss:-69.0

Any idea what this could be?

Thanks

[Jacob]

Also trying the binaries tagged v2.2.0 from my 22.04 linux machine

./chip-tool-release pairing ble-thread 1 hex:0e080000000000010000000300001035060004001fffe002080747c2c1e3cb1d090708fdf836fbbeb82ddc05104afbfca008bdb5d9e39ba9665b65222b030f4f70656e5468726561642d34366137010246a70410277bd96fb2ca2ca217f807412464fb790c0402a0f7f8 20202021 3840

Looks about the same on the device with `I: 145206 [FS]Fail-safe timer expired`

But the rcp logs are a lot of this

Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.680 [I] MeshForwarder-: src:[fe80:0:0:0:b493:aef0:b93c:8565]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.680 [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:1]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.681 [W] Mle-----------: Failed to process UDP: Duplicated
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.785 [I] MeshForwarder-: Received IPv6 UDP msg, len:90, chksum:12c9, ecn:no, from:b693aef0b93c8565, sec:no, prio:net, rss:-68.0
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.786 [I] MeshForwarder-: src:[fe80:0:0:0:b493:aef0:b93c:8565]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.786 [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:1]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.786 [I] Mle-----------: Receive Advertisement (fe80:0:0:0:b493:aef0:b93c:8565,0x9c00)
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.786 [N] Mle-----------: Different partition (peer:636139611, local:1204658966)
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.786 [I] Settings------: Read ChildInfo {rloc:0xbc05, extaddr:b693aef0b93c8565, timeout:240, mode:0x0f, version:4}
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.806 [I] Settings------: Removed ChildInfo {rloc:0xbc05, extaddr:b693aef0b93c8565, timeout:240, mode:0x0f, version:4}
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.806 [I] Mle-----------: Failed to process Advertisement: Drop
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.806 [I] Notifier------: StateChanged (0x00000800) [Child-]
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.817 [I] MeshForwarder-: Received IPv6 UDP msg, len:90, chksum:12c9, ecn:no, from:b693aef0b93c8565, sec:no, prio:net, rss:-69.0
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.817 [I] MeshForwarder-: src:[fe80:0:0:0:b493:aef0:b93c:8565]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.817 [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:1]:19788
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.817 [I] Mle-----------: Receive Advertisement (fe80:0:0:0:b493:aef0:b93c:8565,0x9c00)
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.817 [N] Mle-----------: Different partition (peer:636139611, local:1204658966)
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.818 [I] Mle-----------: Failed to process Advertisement: Drop
Dec 08 01:36:22 raspberrypi otbr-agent[27385]: 06:03:08.902 [I] MeshForwarder-: Received IPv6 UDP msg, len:90, chksum:12c9, ecn:no, from:b693aef0b93c8565, sec:no, prio:net, rss:-68.0

```

Also I thought either of the discover commands would find the pi or the device, but they dont, both time out?

sudo ./chip-tool-release discover commissioners
sudo ./chip-tool-release discover commissionables

service browser finds `_meshcop._udp` at rasperrypi.local with an fd07 address which is pingable by net analzyer

avahi on my linux host finds meshcop though with a failed to resolve and no ipv6 address, but the fd07 from android pings fine from there as well

avahi-browse -r -t _meshcop._udp
+ wlp0s20f3 IPv6 OpenThread BorderRouter #4472 _meshcop._udp local
+ wlp0s20f3 IPv4 OpenThread BorderRouter #4472 _meshcop._udp local
= wlp0s20f3 IPv6 OpenThread BorderRouter #4472 _meshcop._udp local
hostname = [raspberrypi.local]
address = [192.168.1.130]
port = [49155]
txt = ["dn=DefaultDomain" "bb=\240\191" "sq=b" "pt=\022\163\205G" "at=\000\000\000\000\000\001\000\000" "sb=\000\000\001\177" "xa=j\228\242u\162\171Dr" "tv=1.3.0" "xp=\007G\194\193\227\203\029\009" "nn=OpenThread-46a7" "mn=BorderRouter" "vn=OpenThread" "rv=1"]
Failed to resolve service 'OpenThread BorderRouter #4472' of type '_meshcop._udp' in domain 'local': Timeout reached

```

[Charlie]

Hi Jacob,

I have two suggestions to help you debug the issue.

1) Test with Google Home or Apple Homekit with the device to confirm the device has no issue. We have customers report they have successfully run NCS2.2.0 Matter on the above ecosystems. See discussion here Google Home Commissioning Problem - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

2) Make sure you erase the chip before programming nRF52840DK. Provide the full log file from the device and RPi for Preparing accessory device and Commissioning accessory device steps if you still have this issue.

Best regards,

Charlie

[Jacob]

I dont have any apple or google gear.

It was erased
nrfjprog --eraseall -f nrf52
nrfjprog --program build/zephyr/merged.hex -f nrf52 --verify --reset

I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 40118 [TS]Pending Last Known Good Time: 2022-12-08T00:30:33
I: 40124 [TS]Previous Last Known Good Time: 2022-12-08T00:30:33
I: 40130 [TS]Reverted Last Known Good Time to previous value
D: 40135 [ZCL]Emitting ShutDown event
D: 40139 [EVL]LogEvent event number: 0x0000000000020002 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x1 Sys timestamp: 0x0000000000009CCB
D: 40153 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 40159 [DL]Performing factory reset
I: 40190 [DL]Erasing Thread persistent info...
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 1, ce0
I: data wra: 1, 35c


*** Booting Zephyr OS build c0689b16ff12 ***
[1;I: Init CHIP stack
32muart:~$ I: 228 [DL]BLE address: EB:0D:83:3E:2E:65
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: 253 [DL]OpenThread started: OK
I: 256 [DL]Setting OpenThread device type to ROUTER
I: 261 [SVR]Server initializing...
D: 264 [FP]Initializing FabricTable from persistent storage
I: 269 [TS]Last Known Good Time: [unknown]
I: 273 [TS]Setting Last Known Good Time to firmware build time 2022-12-08T00:30:33
I: 285 [DMG]AccessControl: initializing
I: 288 [DMG]Examples::AccessControlDelegate::Init
I: 293 [DMG]AccessControl: setting
I: 296 [DMG]DefaultAclStorage: initializing
I: 300 [DMG]DefaultAclStorage: 0 entries loaded
D: 304 [IN]UDP::Init bind&listen port=5540
E: 308 [IN]SO_REUSEPORT failed: 109
D: 311 [IN]UDP::Init bound to port=5540
D: 315 [IN]BLEBase::Init - setting/overriding transport
D: 320 [IN]TransportMgr initialized
D: 329 [DL]Using Thread extended MAC for hostname.
I: 338 [ZCL]Using ZAP configuration...
D: 342 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 350 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: a0
D: 358 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 365 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: a0
D: 372 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 379 [DMG]AccessControlCluster: initializing
D: 384 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8a76afa1
D: 390 [DL]Boot reason: 6
D: 392 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 396 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 77995859
D: 403 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000193
I: 417 [ZCL]Initiating Admin Commissioning cluster.
D: 421 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to fbc76a25
D: 428 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to b8c12f07
D: 434 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to b8c12f08
I: 441 [ZCL]On/Off set value: 1 0
I: 444 [ZCL]On/off already set to new value
D: 451 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 34db6f63
I: 457 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 463 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 472 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:57117
D: 478 [SC]Assigned local session key ID 57117
D: 482 [SC]Waiting for PBKDF param request
D: 486 [DL]CHIPoBLE advertising set to on
I: 490 [DIS]Updating services using commissioning mode 1
D: 495 [DL]Using Thread extended MAC for hostname.
D: 500 [DL]Using Thread extended MAC for hostname.
I: 505 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 514 [DIS]Failed to advertise commissionable node: 3
E: 519 [DIS]Failed to finalize service update: 1c
I: 523 [DIS]Updating services using commissioning mode 1
D: 528 [DL]Using Thread extended MAC for hostname.
D: 533 [DL]Using Thread extended MAC for hostname.
I: 538 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 547 [DIS]Failed to advertise commissionable node: 3
E: 552 [DIS]Failed to finalize service update: 1c
I: 556 [DIS]Delaying proxy of operational discovery: missing delegate
I: 563 [IN]CASE Server enabling CASE session setups
D: 567 [IN]SecureSession[0x20003708]: Allocated Type:2 LSID:57118
D: 573 [SC]Allocated SecureSession (0x20003708) - waiting for Sigma1 msg
I: 580 [SVR]Joining Multicast groups
D: 583 [ZCL]Emitting StartUp event
D: 587 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000000024A
I: 600 [SVR]Server Listening...
I: 603 [DL]Device Configuration:
I: 606 [DL]  Serial Number: 11223344556677889900
I: 611 [DL]  Vendor Id: 65521 (0xFFF1)
I: 614 [DL]  Product Id: 32773 (0x8005)
I: 618 [DL]  Hardware Version: 0
I: 622 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 627 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 634 [DL]  Manufacturing Date: (not set)
I: 638 [DL]  Device Type: 65535 (0xFFFF)
I: 643 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 647 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 653 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 662 [SVR]Manual pairing code: [34970112332]
I: 667 [DL]CHIP task running
I: 672 [DL]CHIPoBLE advertising started
D: 684 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 264c007f
I: 691 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 695 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 34db6f64
I: 702 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 708 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 716 [DL]NFC Tag emulation started
I: 30675 [DL]CHIPoBLE advertising mode changed to slow
I: 78883 [DL]BLE connection established (ConnId: 0x00)
I: 78888 [DL]Current number of connections: 1/2
I: 78892 [DL]CHIPoBLE advertising stopped
I: 78896 [DL]NFC Tag emulation stopped
D: 79665 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 79672 [BLE]local and remote recv window sizes = 5
I: 79677 [BLE]selected BTP version 4
I: 79680 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 79796 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 79801 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 79808 [IN]BLE EndPoint 0x20012270 Connection Complete
I: 79814 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 79996 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 80005 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 80012 [EM]>>> [E:32105r M:229902967] (U) Msg RX from 0:F11C957B265A7185 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 80024 [EM]Handling via exchange: 32105r, Delegate: 0x20005834
D: 80030 [SC]Received PBKDF param request
D: 80033 [SC]Peer assigned session ID 17480
D: 80037 [SC]Found MRP parameters in the message
D: 80042 [SC]Including MRP parameters in PBKDF param response
I: 80048 [EM]<<< [E:32105r M:92743850] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 80060 [IN](U) Sending msg 92743850 to IP address 'BLE'
D: 80065 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 80073 [SC]Sent PBKDF param response
D: 80146 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 80197 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 80204 [EM]>>> [E:32105r M:229902968] (U) Msg RX from 0:F11C957B265A7185 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 80215 [EM]Found matching exchange: 32105r, Delegate: 0x20005834
D: 80221 [SC]Received spake2p msg1
I: 82151 [EM]<<< [E:32105r M:92743851] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 82162 [IN](U) Sending msg 92743851 to IP address 'BLE'
D: 82167 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
D: 82175 [SC]Sent spake2p msg2
E: 82178 [DL]Long dispatch time: 1981 ms, for event type 16388
D: 82246 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 82297 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 82304 [EM]>>> [E:32105r M:229902969] (U) Msg RX from 0:F11C957B265A7185 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 82315 [EM]Found matching exchange: 32105r, Delegate: 0x20005834
D: 82321 [SC]Received spake2p msg3
D: 82325 [SC]Sending status report. Protocol code 0, exchange 32105
I: 82331 [EM]<<< [E:32105r M:92743852] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 82342 [IN](U) Sending msg 92743852 to IP address 'BLE'
D: 82347 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 82356 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive'
D: 82364 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:57117
D: 82370 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:57117 PSID:17480!
I: 82378 [SVR]Commissioning completed session establishment step
I: 82385 [DIS]Updating services using commissioning mode 0
D: 82390 [DL]Using Thread extended MAC for hostname.
D: 82395 [DL]Using Thread extended MAC for hostname.
I: 82401 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 82410 [DIS]Failed to advertise extended commissionable node: 3
D: 82416 [DIS]Scheduling extended discovery timeout in 900s
E: 82421 [DIS]Failed to finalize service update: 1c
D: 82426 [DL]CHIPoBLE advertising set to off
I: 82430 [SVR]Device completed Rendezvous process
E: 82434 [DL]Long dispatch time: 138 ms, for event type 16388
D: 82446 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 82454 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 82463 [EM]>>> [E:32106r M:115853197] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 82473 [EM]Handling via exchange: 32106r, Delegate: 0x2000fc3c
D: 82479 [IM]Received Read request
D: 82485 [DMG]IM RH moving to [GeneratingReports]
D: 82489 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 82498 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 82503 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 82512 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 82517 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 82526 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 82531 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 82540 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 82545 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 82555 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 82560 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 82569 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 82574 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 82583 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 82588 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 82597 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 82602 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 82611 [DMG]<RE> Sending report (payload has 228 bytes)...
I: 82618 [EM]<<< [E:32106r M:158018282] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 82628 [IN](S) Sending msg 158018282 on secure session with LSID: 57117
D: 82635 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 82642 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 82647 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 82654 [DMG]IM RH moving to [AwaitingDestruction]
D: 82659 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 82746 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 82754 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 82847 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 82855 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 82863 [EM]>>> [E:32107r M:115853198] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 82874 [EM]Handling via exchange: 32107r, Delegate: 0x2000fc3c
D: 82880 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 82887 [FS]GeneralCommissioning: Received ArmFailSafe (30s)
D: 82893 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8a76afa2
D: 82900 [DMG]Command handler moving to [ Preparing]
D: 82904 [DMG]Command handler moving to [AddingComm]
D: 82909 [DMG]Command handler moving to [AddedComma]
D: 82914 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 82921 [EM]<<< [E:32107r M:158018283] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 82932 [IN](S) Sending msg 158018283 on secure session with LSID: 57117
D: 82939 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 82947 [DMG]Command handler moving to [CommandSen]
D: 82951 [DMG]Command handler moving to [AwaitingDe]
E: 82956 [DL]Long dispatch time: 102 ms, for event type 16388
D: 83047 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83055 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 83063 [EM]>>> [E:32108r M:115853199] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 83074 [EM]Handling via exchange: 32108r, Delegate: 0x2000fc3c
D: 83080 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 83103 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8a76afa3
D: 83109 [DMG]Command handler moving to [ Preparing]
D: 83114 [DMG]Command handler moving to [AddingComm]
D: 83119 [DMG]Command handler moving to [AddedComma]
D: 83124 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 83131 [EM]<<< [E:32108r M:158018284] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 83142 [IN](S) Sending msg 158018284 on secure session with LSID: 57117
D: 83149 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 83156 [DMG]Command handler moving to [CommandSen]
D: 83161 [DMG]Command handler moving to [AwaitingDe]
E: 83166 [DL]Long dispatch time: 112 ms, for event type 16388
D: 83247 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83255 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 83263 [EM]>>> [E:32109r M:115853200] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 83274 [EM]Handling via exchange: 32109r, Delegate: 0x2000fc3c
D: 83280 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 83287 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 83293 [DMG]Command handler moving to [ Preparing]
D: 83298 [DMG]Command handler moving to [AddingComm]
D: 83303 [DMG]Command handler moving to [AddedComma]
D: 83308 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 83317 [EM]<<< [E:32109r M:158018285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 83328 [IN](S) Sending msg 158018285 on secure session with LSID: 57117
D: 83334 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 83342 [DMG]Command handler moving to [CommandSen]
D: 83347 [DMG]Command handler moving to [AwaitingDe]
D: 83396 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83404 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 83496 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83504 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 83597 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83605 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 83613 [EM]>>> [E:32110r M:115853201] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 83624 [EM]Handling via exchange: 32110r, Delegate: 0x2000fc3c
D: 83630 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 83637 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 83643 [DMG]Command handler moving to [ Preparing]
D: 83648 [DMG]Command handler moving to [AddingComm]
D: 83653 [DMG]Command handler moving to [AddedComma]
D: 83658 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 83667 [EM]<<< [E:32110r M:158018286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 83678 [IN](S) Sending msg 158018286 on secure session with LSID: 57117
D: 83685 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 83692 [DMG]Command handler moving to [CommandSen]
D: 83697 [DMG]Command handler moving to [AwaitingDe]
D: 83746 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83754 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 83896 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 83904 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
D: 84046 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 84054 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 84062 [EM]>>> [E:32111r M:115853202] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 84073 [EM]Handling via exchange: 32111r, Delegate: 0x2000fc3c
D: 84080 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 84087 [ZCL]OpCreds: Received an AttestationRequest command
I: 84124 [ZCL]OpCreds: AttestationRequest successful.
D: 84128 [DMG]Command handler moving to [ Preparing]
D: 84133 [DMG]Command handler moving to [AddingComm]
D: 84138 [DMG]Command handler moving to [AddedComma]
D: 84143 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 84153 [EM]<<< [E:32111r M:158018287] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 84164 [IN](S) Sending msg 158018287 on secure session with LSID: 57117
D: 84171 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 84178 [DMG]Command handler moving to [CommandSen]
D: 84183 [DMG]Command handler moving to [AwaitingDe]
E: 84188 [DL]Long dispatch time: 134 ms, for event type 16388
D: 84278 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 84285 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 84368 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 84375 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235)
D: 84458 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 84503 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 84511 [EM]>>> [E:32112r M:115853203] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 84522 [EM]Handling via exchange: 32112r, Delegate: 0x2000fc3c
D: 84528 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 84536 [ZCL]OpCreds: Received a CSRRequest command
D: 84541 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 84737 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 84773 [ZCL]OpCreds: CSRRequest successful.
D: 84777 [DMG]Command handler moving to [ Preparing]
D: 84781 [DMG]Command handler moving to [AddingComm]
D: 84786 [DMG]Command handler moving to [AddedComma]
D: 84791 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 84800 [EM]<<< [E:32112r M:158018288] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 84811 [IN](S) Sending msg 158018288 on secure session with LSID: 57117
D: 84817 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 84825 [DMG]Command handler moving to [CommandSen]
D: 84830 [DMG]Command handler moving to [AwaitingDe]
E: 84834 [DL]Long dispatch time: 331 ms, for event type 16388
D: 84908 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 84915 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138)
D: 84998 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 85044 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 85133 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 85142 [EM]>>> [E:32113r M:115853204] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 85153 [EM]Handling via exchange: 32113r, Delegate: 0x2000fc3c
D: 85159 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 85167 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 85230 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 85235 [DMG]Command handler moving to [ Preparing]
D: 85240 [DMG]Command handler moving to [AddingComm]
D: 85245 [DMG]Command handler moving to [AddedComma]
D: 85250 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 85257 [EM]<<< [E:32113r M:158018289] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 85268 [IN](S) Sending msg 158018289 on secure session with LSID: 57117
D: 85275 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 85282 [DMG]Command handler moving to [CommandSen]
D: 85287 [DMG]Command handler moving to [AwaitingDe]
E: 85292 [DL]Long dispatch time: 159 ms, for event type 16388
D: 85357 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 85366 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 85448 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 85457 [EM]>>> [E:32114r M:115853205] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 85468 [EM]Handling via exchange: 32114r, Delegate: 0x2000fc3c
D: 85475 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 85482 [ZCL]OpCreds: Received an AddNOC command
I: 85489 [FP]Validating NOC chain
I: 85550 [FP]NOC chain validation successful
I: 85554 [FP]Added new fabric at index: 0x1
I: 85558 [FP]Assigned compressed fabric ID: 0x407587A9DB9722AF, node ID: 0x0000000000000005
I: 85567 [TS]Last Known Good Time: 2022-12-08T00:30:33
I: 85571 [TS]New proposed Last Known Good Time: 2021-06-10T00:00:00
I: 85577 [TS]Retaining current Last Known Good Time
D: 85582 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94cdb
D: 85589 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94cdc
D: 85616 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000014E6F
I: 85630 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
D: 85639 [DL]Using Thread extended MAC for hostname.
I: 85643 [DIS]Advertise operational node 407587A9DB9722AF-0000000000000005
D: 85650 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94cdd
D: 85657 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94cde
D: 85663 [DMG]Command handler moving to [ Preparing]
D: 85668 [DMG]Command handler moving to [AddingComm]
D: 85673 [DMG]Command handler moving to [AddedComma]
I: 85677 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 85684 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 85691 [EM]<<< [E:32114r M:158018290] (S) Msg TX to 1:FFFFFFFB00000000 [22AF] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 85702 [IN](S) Sending msg 158018290 on secure session with LSID: 57117
D: 85709 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 85716 [DMG]Command handler moving to [CommandSen]
D: 85721 [DMG]Command handler moving to [AwaitingDe]
E: 85726 [DL]Long dispatch time: 278 ms, for event type 16388
D: 85762 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 85771 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 85779 [EM]>>> [E:32115r M:115853206] (S) Msg RX from 1:FFFFFFFB00000000 [22AF] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 85790 [EM]Handling via exchange: 32115r, Delegate: 0x2000fc3c
D: 85796 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 85811 [DMG]Command handler moving to [ Preparing]
D: 85816 [DMG]Command handler moving to [AddingComm]
D: 85820 [DMG]Command handler moving to [AddedComma]
D: 85825 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8a76afa4
D: 85832 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 85839 [EM]<<< [E:32115r M:158018291] (S) Msg TX to 1:FFFFFFFB00000000 [22AF] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 85850 [IN](S) Sending msg 158018291 on secure session with LSID: 57117
D: 85857 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 85864 [DMG]Command handler moving to [CommandSen]
D: 85869 [DMG]Command handler moving to [AwaitingDe]
E: 85874 [DL]Long dispatch time: 103 ms, for event type 16388
D: 85943 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 85951 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 85959 [EM]>>> [E:32116r M:115853207] (S) Msg RX from 1:FFFFFFFB00000000 [22AF] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 85970 [EM]Handling via exchange: 32116r, Delegate: 0x2000fc3c
D: 85976 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 85995 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 86001 [DL]OpenThread State Changed (Flags: 0x1006c100)
D: 86007 [DL]   Network Name: OpenThread
D: 86010 [DL]   PAN Id: 0x46A7
D: 86013 [DL]   Extended PAN Id: 0x0747C2C1E3CB1D09
D: 86018 [DL]   Channel: 16
D: 86020 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 86025 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 86030 [DL]   Device Role: DETACHED
D: 86034 [DL]   Thread Unicast Addresses:
D: 86038 [DL]        fdde:ad00:beef:0:c46f:dcec:916f:ffe1/64 valid
D: 86044 [DL]        fe80::6ce7:5acf:a2a:7330/64 valid preferred
D: 88459 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 88553 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 91028 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 93535 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 93593 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 96068 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 98576 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 98633 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 101108 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 103615 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 103673 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 106147 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 108655 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 108713 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 111187 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 112893 [FS]Fail-safe timer expired
E: 112897 [SVR]Failsafe timer expired
D: 112901 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:57117
I: 112907 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction'
D: 112916 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:57117
E: 112922 [SVR]Commissioning failed (attempt 1): 32
D: 112927 [IN]Clearing BLE pending packets.
I: 112931 [BLE]Releasing end point's BLE connection back to application.
I: 112937 [DL]Closing BLE GATT connection (ConnId 00)
D: 112945 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:57119
D: 112953 [SC]Assigned local session key ID 57119
D: 112958 [SC]Waiting for PBKDF param request
D: 112962 [DL]CHIPoBLE advertising set to on
I: 112966 [DIS]Updating services using commissioning mode 1
D: 112972 [DL]Using Thread extended MAC for hostname.
D: 112977 [DL]Using Thread extended MAC for hostname.
I: 112982 [DIS]Advertise operational node 407587A9DB9722AF-0000000000000005
E: 112989 [DIS]Failed to advertise operational node: 3
D: 112994 [DL]Using Thread extended MAC for hostname.
I: 113000 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 113009 [DIS]Failed to advertise commissionable node: 3
E: 113014 [DIS]Failed to finalize service update: 1c
E: 113019 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 113023 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 113030 [IN]Expiring all sessions for fabric 0x1!!
E: 113037 [FP]Reverting pending fabric data for fabric 0x1
D: 113043 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000001B993
D: 113057 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 113063 [FP]Warning: metadata not found during delete of fabric 0x1
I: 113135 [FP]Fabric (0x1) deleted.
I: 113139 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 113144 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94cdf
D: 113151 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 72f94ce0
I: 113277 [TS]Pending Last Known Good Time: 2022-12-08T00:30:33
I: 113284 [TS]Previous Last Known Good Time: 2022-12-08T00:30:33
I: 113289 [TS]Reverted Last Known Good Time to previous value
D: 113295 [EVL]LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000001BA8F
D: 113309 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 113315 [FP]Warning: metadata not found during delete of fabric 0x1
E: 113324 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 113329 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8a76afa5
D: 113336 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
I: 113344 [NP]Reverting Thread operational dataset
D: 113401 [DMG]Decreasing reference count for CommandHandler, remaining 0
E: 113407 [DMG]Failed to send command response: 3
D: 113412 [DMG]Command handler moving to [AwaitingDe]
E: 113417 [DL]Long dispatch time: 520 ms, for event type 32782
I: 113422 [FS]Fail-safe cleanly disarmed
D: 113428 [DL]OpenThread State Changed (Flags: 0x11002006)
D: 113433 [DL]   Device Role: DISABLED
D: 113437 [DL]   Thread Unicast Addresses:
I: 113441 [DL]BLE GAP connection terminated (reason 0x16)
I: 113447 [DL]Current number of connections: 0/2
I: 113453 [DL]CHIPoBLE advertising started
I: 113458 [DL]NFC Tag emulation started

Heres the device log for bootup into comissioning

[DenverCoder9]

Hi Charlie, 

Are there any updates? I am also running into the same issue with v.2.2.0.

I have tried disabling IGMP snooping on my router solution.I have also tried going back to older versions v2.0.1 and still no luck.

[Charlie]

Hi Jacob and Denver,

Sorry for the late reply. I just set up the same environment to do tests for Matter.

I can recreate the same issue on our company network, but using home network or mobile phone as wifi host, the Matter light sample can successfully join the thread network formed by OTBR and function well.

It is clear that the issue is caused by some configuration or restriction from the local network. In the meantime, please try to test with a different network. I will do further investigation into it and give you feedback later.

Best regards,

Charlie