Error on commissioning step:operational discovery failed: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout

I am trying to test template sample application with nRF52840DK and see that commissioning fails

My environment:

nRF connect sdk:   v2.3.0

nRF connect toolchain:   v2.3.0

chip-tool running on ubuntu

border router: Raspberry Pi with nRf52840 Dongle

I see that BLE connection is successful, but fails  with error -Failed to perform commissioning step 18

Please see the attached file for logs

Appreciate your quick help

Thanks,

Mahesh

: 92797EEA6C7282EA._matterc._udp
E: 89539 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 89543 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 89549 [IN]Expiring all sessions for fabric 0x1!!
E: 89554 [FP]Reverting pending fabric data for fabric 0x1
D: 89559 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015DD7
D: 89573 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89580 [FP]Warning: metadata not found during delete of fabric 0x1
I: 89651 [FP]Fabric (0x1) deleted.
I: 89655 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 89660 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e3
D: 89667 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0e2f1e4
I: 89832 [TS]Pending Last Known Good Time: 2023-02-18T10:14:41
I: 89838 [TS]Previous Last Known Good Time: 2023-02-18T10:14:41
I: 89844 [TS]Reverted Last Known Good Time to previous value
D: 89850 [EVL]LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x0000000000015EF9
D: 89864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 89870 [FP]Warning: metadata not found during delete of fabric 0x1
E: 89879 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 89884 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b98af9cc
D: 89891 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
I: 89898 [NP]Reverting Thread operational dataset
E: 89911 [DL]Long dispatch time: 460 ms, for event type 32782
I: 89916 [FS]Fail-safe cleanly disarmed
I: 89922 [DL]CHIPoBLE advertising started
D: 89926 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 89931 [DL]   Device Role: DISABLED
D: 89934 [DL]   Thread Unicast Addresses:
D: 89938 [DL]        fd6a:8c75:12d3:1:2d9d:1522:2c95:e401/64 valid preferred
D: 89946 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 119926 [DL]CHIPoBLE advertising mode changed to slow
I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 3, 940
I: data wra: 3, 84c


uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 221 [DL]BLE address: F7:C4:D2:DA:E3:6F
I: 232 [DL]OpenThread started: OK
I: 235 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 241 [SVR]Server initializing...
I: 244 [TS]Last Known Good Time: 2023-02-18T10:14:41
I: 249 [TS]Setting Last Known Good Time to firmware build time 2023-03-09T08:28:35
I: 259 [DMG]AccessControl: initializing
I: 262 [DMG]Examples::AccessControlDelegate::Init
I: 266 [DMG]AccessControl: setting
I: 270 [DMG]DefaultAclStorage: initializing
I: 273 [DMG]DefaultAclStorage: 0 entries loaded
D: 278 [IN]UDP::Init bind&listen port=5540
E: 281 [IN]SO_REUSEPORT failed: 109
D: 285 [IN]UDP::Init bound to port=5540
D: 288 [IN]BLEBase::Init - setting/overriding transport
D: 293 [IN]TransportMgr initialized
I: 303 [ZCL]Using ZAP configuration...
I: 308 [DMG]AccessControlCluster: initializing
I: 312 [ZCL]Initiating Admin Commissioning cluster.
D: 319 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25692
I: 325 [DIS]Updating services using commissioning mode 1
I: 331 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 340 [DIS]Failed to advertise commissionable node: 3
E: 345 [DIS]Failed to finalize service update: 1c
I: 349 [DIS]Updating services using commissioning mode 1
I: 355 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
E: 364 [DIS]Failed to advertise commissionable node: 3
E: 369 [DIS]Failed to finalize service update: 1c
I: 373 [DIS]Delaying proxy of operational discovery: missing delegate
I: 379 [IN]CASE Server enabling CASE session setups
D: 384 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:25693
I: 390 [SVR]Joining Multicast groups
I: 393 [SVR]Server Listening...
I: 396 [DL]Device Configuration:
I: 399 [DL]  Serial Number: 11223344556677889900
I: 404 [DL]  Vendor Id: 65521 (0xFFF1)
I: 407 [DL]  Product Id: 32768 (0x8000)
I: 411 [DL]  Hardware Version: 0
I: 415 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 420 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 427 [DL]  Manufacturing Date: (not set)
I: 431 [DL]  Device Type: 65535 (0xFFFF)
I: 436 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 440 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 446 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 455 [SVR]Manual pairing code: [34970112332]
I: 460 [DL]CHIP task running
I: 465 [DL]CHIPoBLE advertising started
I: 20280 [DL]BLE connection established (ConnId: 0x00)
I: 20285 [DL]Current number of connections: 1/1
I: 20289 [DL]CHIPoBLE advertising stopped
I: 21882 [BLE]local and remote recv window sizes = 5
I: 21886 [BLE]selected BTP version 4
I: 21890 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 21972 [IN]BLE EndPoint 0x2000fd28 Connection Complete
I: 21977 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 22063 [EM]>>> [E:32398r M:133325430] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 22076 [EM]<<< [E:32398r M:103602529] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 22087 [IN](U) Sending msg 103602529 to IP address 'BLE'
I: 22198 [EM]>>> [E:32398r M:133325431] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 24073 [EM]<<< [E:32398r M:103602530] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 24084 [IN](U) Sending msg 103602530 to IP address 'BLE'
E: 24089 [DL]Long dispatch time: 1891 ms, for event type 16388
I: 24223 [EM]>>> [E:32398r M:133325432] (U) Msg RX from 0:163838BEE9332817 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 24234 [EM]<<< [E:32398r M:103602531] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 24245 [IN](U) Sending msg 103602531 to IP address 'BLE'
I: 24252 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive'
D: 24259 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:25692
D: 24266 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:25692 PSID:56322!
I: 24275 [SVR]Commissioning completed session establishment step
I: 24281 [DIS]Updating services using commissioning mode 0
I: 24287 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
E: 24296 [DIS]Failed to advertise extended commissionable node: 3
D: 24302 [DIS]Scheduling extended discovery timeout in 900s
E: 24307 [DIS]Failed to finalize service update: 1c
I: 24312 [SVR]Device completed Rendezvous process
I: 24319 [EM]>>> [E:32399r M:259258149] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 24329 [IM]Received Read request
I: 24338 [EM]<<< [E:32399r M:182183003] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 24348 [IN](S) Sending msg 182183003 on secure session with LSID: 25692
I: 24494 [EM]>>> [E:32400r M:259258150] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24505 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 24512 [EM]<<< [E:32400r M:182183004] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24523 [IN](S) Sending msg 182183004 on secure session with LSID: 25692
I: 24584 [EM]>>> [E:32401r M:259258151] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24597 [EM]<<< [E:32401r M:182183005] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24608 [IN](S) Sending msg 182183005 on secure session with LSID: 25692
I: 24674 [EM]>>> [E:32402r M:259258152] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24685 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 24694 [EM]<<< [E:32402r M:182183006] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24705 [IN](S) Sending msg 182183006 on secure session with LSID: 25692
I: 24944 [EM]>>> [E:32403r M:259258153] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24955 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 24964 [EM]<<< [E:32403r M:182183007] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24975 [IN](S) Sending msg 182183007 on secure session with LSID: 25692
I: 25214 [EM]>>> [E:32404r M:259258154] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25226 [ZCL]OpCreds: Received an AttestationRequest command
I: 25262 [ZCL]OpCreds: AttestationRequest successful.
I: 25270 [EM]<<< [E:32404r M:182183008] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25281 [IN](S) Sending msg 182183008 on secure session with LSID: 25692
I: 25619 [EM]>>> [E:32405r M:259258155] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25630 [ZCL]OpCreds: Received a CSRRequest command
I: 25820 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 25856 [ZCL]OpCreds: CSRRequest successful.
I: 25862 [EM]<<< [E:32405r M:182183009] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25873 [IN](S) Sending msg 182183009 on secure session with LSID: 25692
E: 25880 [DL]Long dispatch time: 262 ms, for event type 16388
I: 26204 [EM]>>> [E:32406r M:259258156] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26216 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 26279 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 26285 [EM]<<< [E:32406r M:182183010] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 26296 [IN](S) Sending msg 182183010 on secure session with LSID: 25692
E: 26303 [DL]Long dispatch time: 101 ms, for event type 16388
I: 26656 [EM]>>> [E:32407r M:259258157] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 26667 [ZCL]OpCreds: Received an AddNOC command
I: 26674 [FP]Validating NOC chain
I: 26792 [FP]NOC chain validation successful
I: 26796 [FP]Added new fabric at index: 0x1
I: 26800 [FP]Assigned compressed fabric ID: 0x78D8657DCCA52CBD, node ID: 0x0000000000000001
I: 26808 [TS]Last Known Good Time: 2023-03-09T08:28:35
I: 26813 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 26819 [TS]Retaining current Last Known Good Time
I: 27015 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I: 27024 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 27030 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 27038 [EM]<<< [E:32407r M:182183011] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27048 [IN](S) Sending msg 182183011 on secure session with LSID: 25692
E: 27055 [DL]Long dispatch time: 402 ms, for event type 16388
I: 27106 [EM]>>> [E:32408r M:259258158] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 27123 [EM]<<< [E:32408r M:182183012] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27134 [IN](S) Sending msg 182183012 on secure session with LSID: 25692
I: 27194 [EM]>>> [E:32409r M:259258159] (S) Msg RX from 1:FFFFFFFB00000000 [2CBD] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28666 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
I: 28679 [EM]<<< [E:32409r M:182183013] (S) Msg TX to 1:FFFFFFFB00000000 [2CBD] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28690 [IN](S) Sending msg 182183013 on secure session with LSID: 25692
I: 28697 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 28704 [SVR]Operational advertising enabled
I: 29450 [DIS]Setting operational delegate post init
I: 29458 [SWU]Stopping the watchdog timer
I: 29462 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 29468 [DIS]Updating services using commissioning mode 0
I: 29473 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 29480 [DL]advertising srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 29489 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 29499 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 73766 [IN]Clearing BLE pending packets.
I: 73770 [BLE]Releasing end point's BLE connection back to application.
I: 73776 [DL]Closing BLE GATT connection (ConnId 00)
I: 73901 [DL]BLE GAP connection terminated (reason 0x16)
I: 73906 [DL]Current number of connections: 0/1
I: 84511 [FS]Fail-safe timer expired
E: 84514 [SVR]Failsafe timer expired
D: 84518 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:25692
I: 84524 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction'
D: 84532 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25692
E: 84538 [SVR]Commissioning failed (attempt 1): 32
D: 84545 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:25694
I: 84551 [DIS]Updating services using commissioning mode 1
I: 84556 [DIS]Advertise operational node 78D8657DCCA52CBD-0000000000000001
I: 84564 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84574 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
E: 84580 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 84584 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 84591 [IN]Expiring all sessions for fabric 0x1!!
E: 84595 [FP]Reverting pending fabric data for fabric 0x1
E: 84601 [FP]Warning: metadata not found during delete of fabric 0x1
I: 84612 [FP]Fabric (0x1) deleted.
I: 84615 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 84620 [DIS]Updating services using commissioning mode 1
I: 84626 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I: 84635 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
I: 84642 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 84769 [TS]Pending Last Known Good Time: 2023-03-09T08:28:35
I: 84775 [TS]Previous Last Known Good Time: 2023-03-09T08:28:35
I: 84781 [TS]Reverted Last Known Good Time to previous value
E: 84787 [FP]Warning: metadata not found during delete of fabric 0x1
E: 84795 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 84801 [NP]Reverting Thread operational dataset
E: 84813 [DL]Long dispatch time: 299 ms, for event type 32782
I: 84818 [FS]Fail-safe cleanly disarmed
I: 84823 [DL]CHIPoBLE advertising started
I: 114827 [DL]CHIPoBLE advertising mode changed to slow
I: 114834 [DL]CHIPoBLE advertising started
I: 900318 [SVR]Closing pairing window
D: 900321 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:25694
I: 900327 [DIS]Updating services using commissioning mode 0
I: 900333 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I: 900343 [DL]advertising srp service: E151EA2E0996B80E._matterc._udp
D: 900349 [DIS]Scheduling extended discovery timeout in 900s
I: 900354 [DL]removing srp service: 78D8657DCCA52CBD-0000000000000001._matter._tcp
I: 900362 [DL]CHIPoBLE advertising stopped
chip-tool.log

Parents
  • Hi Mahesh,

    I have contacted internally regarding the issue and will get back to you as soon as I get a response.

    Best Regards,

    Priyanka

  • Hi,

    I have heard back from the internal team.

    It seems that Ubuntu PC does not have IPv6 communication set up with RaspPi.
    Could you provide the following details:
    1) How OT is running on RPi (native or docker)? How it was built (command)?
    2) Do you enable support for PIO/RIO on the Ubuntu PC?
    For example, if the connection between Ubuntu and RaspPi is realized through wlan0 then:
    sudo sysctl -w net.ipv6.conf.wlan0.accept_ra=1
    sudo sysctl -w net.ipv6.conf.wlan0.accept_ra_rt_info_max_plen=64

    You can also refer here: https://openthread.io/codelabs/openthread-border-router#6
  • 1)How OT is running on RPi (native or docker)? How it was built (command)?

        RPi+nRF52640 dongle (native)

        To setup otbr I followed guidelines give at below url

              https://openthread.io/codelabs/openthread-border-router#1

    2) Do you enable support for PIO/RIO on the Ubuntu PC?

        I am using ubuntu to commission the device through BLE  using following command (I believe IPv6 support on ubuntu should not matter)

         ./chip-tool-debug pairing ble-thread 3 hex:0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef000005109dcc6c00af763734178aa5a2d8457380030a4f70656e5468726561640102fa08041014cf277ce865e0766a7a1bb8da91cf480c0402a0f7f8 20202021 3840

    I am following the procedure given at following url for testing developer.nordicsemi.com/.../chip_tool_guide.html

    see the attached file(otbt-data.txt) for details on status and settings

    Thanks,

    Mahesh

    [email protected]:~ $ sudo service otbr-agent status
    ● otbr-agent.service - OpenThread Border Router Agent
         Loaded: loaded (/lib/systemd/system/otbr-agent.service; enabled; vendor preset: enabled)
         Active: active (running) since Thu 2023-03-16 20:50:31 IST; 1h 16min ago
        Process: 2576 ExecStartPre=service mdns start (code=exited, status=0/SUCCESS)
       Main PID: 2582 (otbr-agent)
          Tasks: 1 (limit: 1830)
            CPU: 5.154s
         CGroup: /system.slice/otbr-agent.service
                 └─2582 /usr/sbin/otbr-agent -I wpan0 -B wlan0 spinel+hdlc+uart:///dev/ttyACM0?uart-baudrate=1000000 trel://wlan0
    
    Mar 16 22:06:33 OTBR otbr-agent[2582]: 01:16:02.170 [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    Mar 16 22:06:34 OTBR otbr-agent[2582]: 01:16:02.176 [I] MeshForwarder-: Sent IPv6 UDP msg, len:90, chksum:4d75, ecn:no, to:0xffff, sec:no, prio>
    Mar 16 22:06:34 OTBR otbr-agent[2582]: 01:16:02.177 [I] MeshForwarder-:     src:[fe80:0:0:0:4079:1153:fc78:9d2f]:19788
    Mar 16 22:06:34 OTBR otbr-agent[2582]: 01:16:02.177 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    Mar 16 22:06:35 OTBR otbr-agent[2582]: 01:16:03.674 [I] BorderRouter--: Sent Neighbor Solicitation to fe80:0:0:0:f2b4:d2ff:fe72:4a88 - attempt:>
    Mar 16 22:06:35 OTBR otbr-agent[2582]: 01:16:03.681 [I] BorderRouter--: Received NA from router fe80:0:0:0:f2b4:d2ff:fe72:4a88
    Mar 16 22:07:06 OTBR otbr-agent[2582]: 01:16:34.618 [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    Mar 16 22:07:06 OTBR otbr-agent[2582]: 01:16:34.623 [I] MeshForwarder-: Sent IPv6 UDP msg, len:90, chksum:21ab, ecn:no, to:0xffff, sec:no, prio>
    Mar 16 22:07:06 OTBR otbr-agent[2582]: 01:16:34.623 [I] MeshForwarder-:     src:[fe80:0:0:0:4079:1153:fc78:9d2f]:19788
    Mar 16 22:07:06 OTBR otbr-agent[2582]: 01:16:34.624 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [email protected]:~ $ sudo ot-ctl state
    leader
    Done
    [email protected]:~ $ sudo ot-ctl netdata show
    Prefixes:
    fd6a:8c75:12d3:1::/64 paos low 8800
    Routes:
    fdde:ad00:beef:cafe::/64 s med 8800
    fd6d:8c75:79aa:0::/64 s med 8800
    Services:
    44970 01 5a000500000e10 s 8800
    44970 5d fddead00beef00004b850af36b3860d2d126 s 8800
    Done
    [email protected]:~ $ sudo ot-ctl ipaddr
    fdde:ad00:beef:0:0:ff:fe00:fc11
    fd6a:8c75:12d3:1:bcf7:628e:f6f3:7600
    fdde:ad00:beef:0:0:ff:fe00:fc10
    fdde:ad00:beef:0:0:ff:fe00:fc38
    fdde:ad00:beef:0:0:ff:fe00:fc00
    fdde:ad00:beef:0:0:ff:fe00:8800
    fdde:ad00:beef:0:4b85:af3:6b38:60d2
    fe80:0:0:0:4079:1153:fc78:9d2f
    Done
    [email protected]:~ $ sudo ot-ctl ipaddr
    fdde:ad00:beef:0:0:ff:fe00:fc11
    fd6a:8c75:12d3:1:bcf7:628e:f6f3:7600
    fdde:ad00:beef:0:0:ff:fe00:fc10
    fdde:ad00:beef:0:0:ff:fe00:fc38
    fdde:ad00:beef:0:0:ff:fe00:fc00
    fdde:ad00:beef:0:0:ff:fe00:8800
    fdde:ad00:beef:0:4b85:af3:6b38:60d2
    fe80:0:0:0:4079:1153:fc78:9d2f
    Done
    [email protected]:~ $ sudo ot-ctl dataset active -x
    0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef000005109dcc6c00af763734178aa5a2d8457380030a4f70656e5468726561640102fa08041014cf277ce865e0766a7a1bb8da91cf480c0402a0f7f8
    Done
    
    

  • I have conveyed this to experts and will get back to you soon.

    -Priyanka

Reply Children
  • Thanks. I have updated this to the team as well. Will get back to you as soon as I get a response from the experts.

  • Hi,

    Sorry for the delay. The team is currently a bit busy and please do bear with us. I will get back to you as soon as possible, with a solution.

  • Hi Mahesh,

    I have heard back from them.

    Regarding this,

    maheswara said:
    I am using ubuntu to commission the device through BLE  using following command (I believe IPv6 support on ubuntu should not matter)

    They say the following:

    "Actually it does matter. The first stage of a commissioning is done using BLE and I believe it succeeded. Then the device successfully joined the Thread network, what we can see based on this log from CHIPTool: "Successfully finished commissioning step 'ThreadNetworkEnable'".
    Then the CHIPTool wants to resolve the Matter device IP address using the DNS-SD and I can see in logs that it fails."
    So, as in the previous comments that I had mentioned, the Raspberry Pi must support RIO, so that the CHIPTool could receive IPv6 prefix from Thread Border Router and then perform DNS discovery in Thread network created by the Thread Border Router. Could you confirm that you performed the steps that we had mentioned in the previous comments?
    -
  • Thanks for the help. Now I am using chipttol with ubuntu over wifi and discovery seems be successful but failing in OperationalSessionSetup

    Appreciate your quick help to resolve the issues

    attached the failure logs

    Thanks,

    Mahesh.

    Connected via Serial Port with settings /dev/ttyACM0 115200 8n1 rtscts:off
    
    
    ~x~~x~: command not found
    uart:~$
    uart:~$ I: 100495 [DL]BLE connection established (ConnId: 0x00)
    I: 100500 [DL]Current number of connections: 1/1
    I: 100504 [DL]CHIPoBLE advertising stopped
    I: 100508 [DL]NFC Tag emulation stopped
    I: 102232 [BLE]local and remote recv window sizes = 5
    I: 102236 [BLE]selected BTP version 4
    I: 102240 [BLE]using BTP fragment sizes rx 244 / tx 244.
    D: 102322 [IN]BLE EndPoint 0x200124d8 Connection Complete
    I: 102327 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
    I: 102413 [EM]>>> [E:40953r M:43039066] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    I: 102426 [EM]<<< [E:40953r M:257634583] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 102437 [IN](U) Sending msg 257634583 to IP address 'BLE'
    I: 102548 [EM]>>> [E:40953r M:43039067] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    I: 104454 [EM]<<< [E:40953r M:257634584] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 104465 [IN](U) Sending msg 257634584 to IP address 'BLE'
    E: 104470 [DL]Long dispatch time: 1922 ms, for event type 16388
    I: 104573 [EM]>>> [E:40953r M:43039068] (U) Msg RX from 0:611061BA73AA7F52 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    I: 104584 [EM]<<< [E:40953r M:257634585] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 104595 [IN](U) Sending msg 257634585 to IP address 'BLE'
    I: 104602 [SC]SecureSession[0x20003568]: Moving from state 'kEstablishing' --> 'kActive'
    D: 104609 [IN]SecureSession[0x20003568]: Activated - Type:1 LSID:29298
    D: 104616 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:29298 PSID:26634!
    I: 104625 [SVR]Commissioning completed session establishment step
    I: 104631 [DIS]Updating services using commissioning mode 0
    I: 104637 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
    E: 104647 [DIS]Failed to advertise extended commissionable node: 3
    D: 104652 [DIS]Scheduling extended discovery timeout in 900s
    E: 104658 [DIS]Failed to finalize service update: 1c
    I: 104663 [SVR]Device completed Rendezvous process
    I: 104710 [EM]>>> [E:40954r M:217898161] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 104720 [IM]Received Read request
    I: 104729 [EM]<<< [E:40954r M:208773525] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 104739 [IN](S) Sending msg 208773525 on secure session with LSID: 29298
    I: 104979 [EM]>>> [E:40955r M:217898162] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 104990 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
    I: 104997 [EM]<<< [E:40955r M:208773526] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 105008 [IN](S) Sending msg 208773526 on secure session with LSID: 29298
    I: 105069 [EM]>>> [E:40956r M:217898163] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 105083 [EM]<<< [E:40956r M:208773527] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 105094 [IN](S) Sending msg 208773527 on secure session with LSID: 29298
    I: 105159 [EM]>>> [E:40957r M:217898164] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 105170 [ZCL]OpCreds: Certificate Chain request received for PAI
    I: 105179 [EM]<<< [E:40957r M:208773528] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 105190 [IN](S) Sending msg 208773528 on secure session with LSID: 29298
    I: 105474 [EM]>>> [E:40958r M:217898165] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 105485 [ZCL]OpCreds: Certificate Chain request received for DAC
    I: 105494 [EM]<<< [E:40958r M:208773529] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 105505 [IN](S) Sending msg 208773529 on secure session with LSID: 29298
    I: 105744 [EM]>>> [E:40959r M:217898166] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 105756 [ZCL]OpCreds: Received an AttestationRequest command
    I: 105792 [ZCL]OpCreds: AttestationRequest successful.
    I: 105800 [EM]<<< [E:40959r M:208773530] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 105811 [IN](S) Sending msg 208773530 on secure session with LSID: 29298
    I: 106194 [EM]>>> [E:40960r M:217898167] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 106205 [ZCL]OpCreds: Received a CSRRequest command
    I: 106396 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 106432 [ZCL]OpCreds: CSRRequest successful.
    I: 106438 [EM]<<< [E:40960r M:208773531] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 106449 [IN](S) Sending msg 208773531 on secure session with LSID: 29298
    E: 106456 [DL]Long dispatch time: 263 ms, for event type 16388
    I: 106779 [EM]>>> [E:40961r M:217898168] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 106791 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 106853 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    I: 106859 [EM]<<< [E:40961r M:208773532] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 106871 [IN](S) Sending msg 208773532 on secure session with LSID: 29298
    I: 107276 [EM]>>> [E:40962r M:217898169] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 107287 [ZCL]OpCreds: Received an AddNOC command
    I: 107295 [FP]Validating NOC chain
    I: 107411 [FP]NOC chain validation successful
    I: 107415 [FP]Added new fabric at index: 0x1
    I: 107419 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001
    I: 107427 [TS]Last Known Good Time: 2023-03-19T22:11:21
    I: 107432 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
    I: 107438 [TS]Retaining current Last Known Good Time
    I: 107465 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
    I: 107474 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 107480 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    I: 107488 [EM]<<< [E:40962r M:208773533] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 107499 [IN](S) Sending msg 208773533 on secure session with LSID: 29298
    E: 107506 [DL]Long dispatch time: 233 ms, for event type 16388
    I: 107591 [EM]>>> [E:40963r M:217898170] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 107608 [EM]<<< [E:40963r M:208773534] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 107619 [IN](S) Sending msg 208773534 on secure session with LSID: 29298
    I: 107679 [EM]>>> [E:40964r M:217898171] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 108701 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
    I: 108714 [EM]<<< [E:40964r M:208773535] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 108725 [IN](S) Sending msg 208773535 on secure session with LSID: 29298
    I: 108732 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 108739 [SVR]Operational advertising enabled
    I: 109112 [DIS]Setting operational delegate post init
    I: 109121 [SWU]Stopping the watchdog timer
    I: 109125 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 109131 [DIS]Updating services using commissioning mode 0
    I: 109137 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 109144 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 109152 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
    I: 109162 [DL]advertising srp service: 39C191837C681C04._matterc._udp
    I: 111155 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 111166 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e98
    I: 111174 [IN]CASE Server disabling CASE session setups
    I: 111179 [EM]<<< [E:40965r M:257634586 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 111192 [IN](U) Sending msg 257634586 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 111202 [SC]Received Sigma1 msg
    I: 111210 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
    I: 111438 [EM]<<< [E:40965r M:257634587 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
    I: 111450 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 111462 [SC]Sent Sigma2 msg
    D: 112271 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
    I: 112279 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 112291 [EM]<<< [E:40965r M:257634588 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 112303 [IN](U) Sending msg 257634588 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 112339 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 113200 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    D: 113477 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
    I: 113486 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 113497 [EM]<<< [E:40965r M:257634589 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 113510 [IN](U) Sending msg 257634589 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 114291 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    I: 115693 [IN](U) Sending msg 257634587 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    D: 115939 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
    I: 115947 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 115959 [EM]<<< [E:40965r M:257634590 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 115972 [IN](U) Sending msg 257634590 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    E: 117693 [EM]Failed to Send CHIP MessageCounter:257634587 on exchange 40965r sendCount: 4 max retries: 4
    D: 118817 [IN]Received a duplicate message with MessageCounter:43039069 on exchange 40965r
    I: 118825 [EM]>>> [E:40965r M:43039069] (U) Msg RX from 0:51BF38E8344F8EEC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 118837 [EM]<<< [E:40965r M:257634591 (Ack:43039069)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 118850 [IN](U) Sending msg 257634591 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:52038'
    D: 127026 [IN]Clearing BLE pending packets.
    I: 127030 [BLE]Releasing end point's BLE connection back to application.
    I: 127037 [DL]Closing BLE GATT connection (ConnId 00)
    I: 127161 [DL]BLE GAP connection terminated (reason 0x16)
    I: 127166 [DL]Current number of connections: 0/1
    E: 148162 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2
    E: 148171 [IN]CASE Session establishment failed: 32
    I: 148176 [IN]CASE Server enabling CASE session setups
    D: 148181 [IN]SecureSession[0x20003620]: Released - Type:2 LSID:29299
    D: 148187 [IN]SecureSession[0x20003620]: Allocated Type:2 LSID:29300
    I: 164996 [FS]Fail-safe timer expired
    E: 165000 [SVR]Failsafe timer expired
    D: 165003 [IN]SecureSession[0x20003568]: MarkForEviction Type:1 LSID:29298
    I: 165010 [SC]SecureSession[0x20003568]: Moving from state 'kActive' --> 'kPendingEviction'
    D: 165018 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29298
    E: 165024 [SVR]Commissioning failed (attempt 1): 32
    D: 165031 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:29301
    I: 165037 [DIS]Updating services using commissioning mode 1
    I: 165043 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 165051 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
    I: 165060 [DL]advertising srp service: 39C191837C681C04._matterc._udp
    E: 165067 [ZCL]OpCreds: Got FailSafeTimerExpired
    E: 165071 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
    D: 165078 [IN]Expiring all sessions for fabric 0x1!!
    E: 165082 [FP]Reverting pending fabric data for fabric 0x1
    E: 165089 [FP]Warning: metadata not found during delete of fabric 0x1
    I: 165100 [FP]Fabric (0x1) deleted.
    I: 165103 [ZCL]OpCreds: Fabric index 0x1 was removed
    I: 165108 [DIS]Updating services using commissioning mode 1
    I: 165114 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
    I: 165124 [DL]advertising srp service: 39C191837C681C04._matterc._udp
    I: 165130 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 165293 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21
    I: 165300 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21
    I: 165306 [TS]Reverted Last Known Good Time to previous value
    E: 165313 [FP]Warning: metadata not found during delete of fabric 0x1
    E: 165323 [ZCL]OpCreds: failed to delete fabric at index 1: d8
    I: 165330 [NP]Reverting Thread operational dataset
    E: 165342 [DL]Long dispatch time: 342 ms, for event type 32782
    I: 165348 [FS]Fail-safe cleanly disarmed
    I: 165353 [DL]CHIPoBLE advertising started
    I: 165360 [DL]NFC Tag emulation started
    I: 195357 [DL]CHIPoBLE advertising mode changed to slow
    I: 195364 [DL]CHIPoBLE advertising started
    I: 900328 [SVR]Closing pairing window
    D: 900332 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:29301
    I: 900338 [DIS]Updating services using commissioning mode 0
    I: 900344 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
    I: 900353 [DL]advertising srp service: 39C191837C681C04._matterc._udp
    D: 900359 [DIS]Scheduling extended discovery timeout in 900s
    I: 900365 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 900372 [DL]CHIPoBLE advertising stopped
    I: 900376 [DL]NFC Tag emulation stopped
    D: 1800365 [DIS]Extended discovery timed out
    I: 1800369 [DIS]Updating services using commissioning mode 0
    I: 1800374 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 1800382 [DL]removing srp service: 39C191837C681C04._matterc._udp
    I: nRF5 802154 radio initialized
    I: 4 Sectors of 4096 bytes
    I: alloc wra: 1, e68
    I: data wra: 1, 2a8
    
    
    uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
    I: Init CHIP stack
    I: 223 [DL]BLE address: C4:59:9B:B5:0D:6F
    I: 234 [DL]OpenThread started: OK
    I: 237 [DL]Setting OpenThread device type to MINIMAL END DEVICE
    I: 242 [SVR]Server initializing...
    I: 246 [TS]Last Known Good Time: 2023-03-19T22:11:21
    I: 252 [DMG]AccessControl: initializing
    I: 255 [DMG]Examples::AccessControlDelegate::Init
    I: 260 [DMG]AccessControl: setting
    I: 263 [DMG]DefaultAclStorage: initializing
    I: 266 [DMG]DefaultAclStorage: 0 entries loaded
    D: 271 [IN]UDP::Init bind&listen port=5540
    E: 275 [IN]SO_REUSEPORT failed: 109
    D: 278 [IN]UDP::Init bound to port=5540
    D: 281 [IN]BLEBase::Init - setting/overriding transport
    D: 286 [IN]TransportMgr initialized
    I: 296 [ZCL]Using ZAP configuration...
    I: 301 [DMG]AccessControlCluster: initializing
    I: 305 [ZCL]Initiating Admin Commissioning cluster.
    D: 312 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26314
    I: 318 [DIS]Updating services using commissioning mode 1
    I: 324 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
    E: 333 [DIS]Failed to advertise commissionable node: 3
    E: 338 [DIS]Failed to finalize service update: 1c
    I: 342 [DIS]Updating services using commissioning mode 1
    I: 349 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
    E: 358 [DIS]Failed to advertise commissionable node: 3
    E: 362 [DIS]Failed to finalize service update: 1c
    I: 367 [DIS]Delaying proxy of operational discovery: missing delegate
    I: 373 [IN]CASE Server enabling CASE session setups
    D: 378 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26315
    I: 383 [SVR]Joining Multicast groups
    I: 387 [SVR]Server Listening...
    I: 390 [DL]Device Configuration:
    I: 393 [DL]  Serial Number: 11223344556677889900
    I: 397 [DL]  Vendor Id: 65521 (0xFFF1)
    I: 401 [DL]  Product Id: 32768 (0x8000)
    I: 405 [DL]  Hardware Version: 0
    I: 408 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
    I: 414 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
    I: 421 [DL]  Manufacturing Date: (not set)
    I: 425 [DL]  Device Type: 65535 (0xFFFF)
    I: 430 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
    I: 434 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    I: 440 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
    I: 449 [SVR]Manual pairing code: [34970112332]
    I: 454 [DL]CHIP task running
    I: 459 [DL]CHIPoBLE advertising started
    I: 30463 [DL]CHIPoBLE advertising mode changed to slow
    I: 30470 [DL]CHIPoBLE advertising started
    I: 96070 [DL]BLE connection established (ConnId: 0x00)
    I: 96075 [DL]Current number of connections: 1/1
    I: 96079 [DL]CHIPoBLE advertising stopped
    I: 97625 [BLE]local and remote recv window sizes = 5
    I: 97630 [BLE]selected BTP version 4
    I: 97633 [BLE]using BTP fragment sizes rx 244 / tx 244.
    D: 97715 [IN]BLE EndPoint 0x2000fd28 Connection Complete
    I: 97720 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
    I: 97807 [EM]>>> [E:5139r M:223393267] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    I: 97819 [EM]<<< [E:5139r M:49097240] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 97831 [IN](U) Sending msg 49097240 to IP address 'BLE'
    I: 97942 [EM]>>> [E:5139r M:223393268] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    I: 99819 [EM]<<< [E:5139r M:49097241] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 99830 [IN](U) Sending msg 49097241 to IP address 'BLE'
    E: 99835 [DL]Long dispatch time: 1894 ms, for event type 16388
    I: 99966 [EM]>>> [E:5139r M:223393269] (U) Msg RX from 0:1348855C44E83875 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    I: 99978 [EM]<<< [E:5139r M:49097242] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 99989 [IN](U) Sending msg 49097242 to IP address 'BLE'
    I: 99995 [SC]SecureSession[0x20003550]: Moving from state 'kEstablishing' --> 'kActive'
    D: 100003 [IN]SecureSession[0x20003550]: Activated - Type:1 LSID:26314
    D: 100009 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:26314 PSID:55740!
    I: 100018 [SVR]Commissioning completed session establishment step
    I: 100024 [DIS]Updating services using commissioning mode 0
    I: 100031 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
    E: 100040 [DIS]Failed to advertise extended commissionable node: 3
    D: 100046 [DIS]Scheduling extended discovery timeout in 900s
    E: 100051 [DIS]Failed to finalize service update: 1c
    I: 100057 [SVR]Device completed Rendezvous process
    I: 100063 [EM]>>> [E:5140r M:155586262] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 100073 [IM]Received Read request
    I: 100082 [EM]<<< [E:5140r M:227813834] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 100092 [IN](S) Sending msg 227813834 on secure session with LSID: 26314
    I: 100238 [EM]>>> [E:5141r M:155586263] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 100249 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
    I: 100255 [EM]<<< [E:5141r M:227813835] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 100266 [IN](S) Sending msg 227813835 on secure session with LSID: 26314
    I: 100372 [EM]>>> [E:5142r M:155586264] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 100386 [EM]<<< [E:5142r M:227813836] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 100397 [IN](S) Sending msg 227813836 on secure session with LSID: 26314
    I: 100462 [EM]>>> [E:5143r M:155586265] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 100474 [ZCL]OpCreds: Certificate Chain request received for PAI
    I: 100483 [EM]<<< [E:5143r M:227813837] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 100493 [IN](S) Sending msg 227813837 on secure session with LSID: 26314
    I: 100732 [EM]>>> [E:5144r M:155586266] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 100744 [ZCL]OpCreds: Certificate Chain request received for DAC
    I: 100753 [EM]<<< [E:5144r M:227813838] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 100764 [IN](S) Sending msg 227813838 on secure session with LSID: 26314
    I: 101003 [EM]>>> [E:5145r M:155586267] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 101014 [ZCL]OpCreds: Received an AttestationRequest command
    I: 101051 [ZCL]OpCreds: AttestationRequest successful.
    I: 101059 [EM]<<< [E:5145r M:227813839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 101070 [IN](S) Sending msg 227813839 on secure session with LSID: 26314
    I: 101407 [EM]>>> [E:5146r M:155586268] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 101419 [ZCL]OpCreds: Received a CSRRequest command
    I: 101609 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 101645 [ZCL]OpCreds: CSRRequest successful.
    I: 101652 [EM]<<< [E:5146r M:227813840] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 101662 [IN](S) Sending msg 227813840 on secure session with LSID: 26314
    E: 101669 [DL]Long dispatch time: 263 ms, for event type 16388
    I: 101993 [EM]>>> [E:5147r M:155586269] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 102004 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 102067 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    I: 102074 [EM]<<< [E:5147r M:227813841] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 102085 [IN](S) Sending msg 227813841 on secure session with LSID: 26314
    E: 102092 [DL]Long dispatch time: 101 ms, for event type 16388
    I: 102444 [EM]>>> [E:5148r M:155586270] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 102456 [ZCL]OpCreds: Received an AddNOC command
    I: 102463 [FP]Validating NOC chain
    I: 102581 [FP]NOC chain validation successful
    I: 102585 [FP]Added new fabric at index: 0x1
    I: 102589 [FP]Assigned compressed fabric ID: 0xEB2BB6B80AC66AB2, node ID: 0x0000000000000001
    I: 102597 [TS]Last Known Good Time: 2023-03-19T22:11:21
    I: 102602 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
    I: 102609 [TS]Retaining current Last Known Good Time
    I: 102633 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
    I: 102642 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 102649 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    I: 102656 [EM]<<< [E:5148r M:227813842] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 102667 [IN](S) Sending msg 227813842 on secure session with LSID: 26314
    E: 102674 [DL]Long dispatch time: 233 ms, for event type 16388
    I: 102760 [EM]>>> [E:5149r M:155586271] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 102777 [EM]<<< [E:5149r M:227813843] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 102787 [IN](S) Sending msg 227813843 on secure session with LSID: 26314
    I: 102848 [EM]>>> [E:5150r M:155586272] (S) Msg RX from 1:FFFFFFFB00000000 [6AB2] --- Type 0001:08 (IM:InvokeCommandRequest)
    I: 106165 [DL]SRP Client was started, detected server: fdde:ad00:beef:0000:4b85:0af3:6b38:60d2
    I: 106178 [EM]<<< [E:5150r M:227813844] (S) Msg TX to 1:FFFFFFFB00000000 [6AB2] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 106189 [IN](S) Sending msg 227813844 on secure session with LSID: 26314
    I: 106195 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 106202 [SVR]Operational advertising enabled
    I: 106835 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 106847 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004e80
    I: 106854 [IN]CASE Server disabling CASE session setups
    I: 106861 [EM]<<< [E:5151r M:49097243 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 106873 [IN](U) Sending msg 49097243 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 106884 [SC]Received Sigma1 msg
    I: 106891 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
    I: 106946 [DIS]Setting operational delegate post init
    I: 107123 [EM]<<< [E:5151r M:49097244 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
    I: 107136 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 107146 [SC]Sent Sigma2 msg
    I: 107153 [SWU]Stopping the watchdog timer
    I: 107158 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 107165 [DIS]Updating services using commissioning mode 0
    I: 107171 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 107179 [DL]advertising srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 107188 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
    I: 107198 [DL]advertising srp service: 44619005BF223B89._matterc._udp
    D: 107935 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
    I: 107944 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 107955 [EM]<<< [E:5151r M:49097245 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 107968 [IN](U) Sending msg 49097245 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 108049 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 108918 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    D: 109167 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
    I: 109175 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 109187 [EM]<<< [E:5151r M:49097246 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 109200 [IN](U) Sending msg 49097246 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 109962 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    D: 111030 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
    I: 111039 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 111050 [EM]<<< [E:5151r M:49097247 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 111063 [IN](U) Sending msg 49097247 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    I: 111405 [IN](U) Sending msg 49097244 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    E: 113538 [EM]Failed to Send CHIP MessageCounter:49097244 on exchange 5151r sendCount: 4 max retries: 4
    D: 114123 [IN]Received a duplicate message with MessageCounter:223393270 on exchange 5151r
    I: 114131 [EM]>>> [E:5151r M:223393270] (U) Msg RX from 0:D2BF40447208191C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
    I: 114143 [EM]<<< [E:5151r M:49097248 (Ack:223393270)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
    I: 114156 [IN](U) Sending msg 49097248 to IP address 'UDP:[fd6d:8c75:79aa:0:684b:8d9f:46f1:3a86]:34647'
    D: 122735 [IN]Clearing BLE pending packets.
    I: 122739 [BLE]Releasing end point's BLE connection back to application.
    I: 122745 [DL]Closing BLE GATT connection (ConnId 00)
    I: 122870 [DL]BLE GAP connection terminated (reason 0x16)
    I: 122875 [DL]Current number of connections: 0/1
    E: 143847 [SC]CASESession timed out while waiting for a response from the peer. Current state was 2
    E: 143856 [IN]CASE Session establishment failed: 32
    I: 143860 [IN]CASE Server enabling CASE session setups
    D: 143865 [IN]SecureSession[0x20003608]: Released - Type:2 LSID:26315
    D: 143872 [IN]SecureSession[0x20003608]: Allocated Type:2 LSID:26316
    I: 160254 [FS]Fail-safe timer expired
    E: 160257 [SVR]Failsafe timer expired
    D: 160261 [IN]SecureSession[0x20003550]: MarkForEviction Type:1 LSID:26314
    I: 160267 [SC]SecureSession[0x20003550]: Moving from state 'kActive' --> 'kPendingEviction'
    D: 160276 [IN]SecureSession[0x20003550]: Released - Type:1 LSID:26314
    E: 160282 [SVR]Commissioning failed (attempt 1): 32
    D: 160289 [IN]SecureSession[0x20003550]: Allocated Type:1 LSID:26317
    I: 160295 [DIS]Updating services using commissioning mode 1
    I: 160300 [DIS]Advertise operational node EB2BB6B80AC66AB2-0000000000000001
    I: 160308 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
    I: 160318 [DL]advertising srp service: 44619005BF223B89._matterc._udp
    E: 160324 [ZCL]OpCreds: Got FailSafeTimerExpired
    E: 160329 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
    D: 160335 [IN]Expiring all sessions for fabric 0x1!!
    E: 160340 [FP]Reverting pending fabric data for fabric 0x1
    E: 160346 [FP]Warning: metadata not found during delete of fabric 0x1
    I: 160357 [FP]Fabric (0x1) deleted.
    I: 160361 [ZCL]OpCreds: Fabric index 0x1 was removed
    I: 160365 [DIS]Updating services using commissioning mode 1
    I: 160372 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
    I: 160381 [DL]advertising srp service: 44619005BF223B89._matterc._udp
    I: 160388 [DL]removing srp service: EB2BB6B80AC66AB2-0000000000000001._matter._tcp
    I: 160509 [TS]Pending Last Known Good Time: 2023-03-19T22:11:21
    I: 160515 [TS]Previous Last Known Good Time: 2023-03-19T22:11:21
    I: 160521 [TS]Reverted Last Known Good Time to previous value
    E: 160527 [FP]Warning: metadata not found during delete of fabric 0x1
    E: 160536 [ZCL]OpCreds: failed to delete fabric at index 1: d8
    I: 160542 [NP]Reverting Thread operational dataset
    E: 160554 [DL]Long dispatch time: 297 ms, for event type 32782
    I: 160559 [FS]Fail-safe cleanly disarmed
    I: 160565 [DL]CHIPoBLE advertising started
    I: 190569 [DL]CHIPoBLE advertising mode changed to slow
    I: 190576 [DL]CHIPoBLE advertising started
    chiptool-template-errors.txt

Related