Unable to connect Matter Light Switch to Home Assistant

[Vincent124]

Hello,

I'm trying to set up a Home Assistant with different Matter devices. For this I am using the nRF Connect Matter Samples "light_switch" and "light_bulb". 

For commissioning I'm using the Home Assistant Mobile App while following this Documentation: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.5.0/nrf/samples/matter/light_switch/README.html#matter-light-switch-sample-remote-control-commissioning. 

Sadly I am unable to connect my light switch. With the bulb I didn't have any problems. I just scanned the Code via the App and got it to connect. But when I do the same with the light switch then after trying to connect the device with the Home Assistant for a while, the App says "An Error has occured".

I did enable the advertising mode manually as it is said in the documentation. My Border Router also works fine. After scanning the Code and starting the commissioning, the Matter device is trying to connect but after working a while the Error occurs. 

For some reason after this, the device is somehow connected to the Border Router. I can see that in the Web-GUI. But in my Home Assistant device/entity list there is no Matter light switch.

The Home Assistant Matter Server Log prints this:

2024-01-04 08:54:52 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:55:06 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:55:37 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:55:51 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:55:51 core-matter-server matter_server.server.device_controller[65] WARNING Unable to subscribe to Node 9 as it is unavailable, will retry later in the background.
2024-01-04 08:56:22 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:56:36 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:57:07 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:57:21 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:57:21 core-matter-server matter_server.server.device_controller[65] WARNING Unable to subscribe to Node 10 as it is unavailable, will retry later in the background.
2024-01-04 08:57:39 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetching the latest PAA root certificates from DCL.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetched 0 PAA root certificates from DCL.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetching the latest PAA root certificates from Git.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetched 0 PAA root certificates from Git.
2024-01-04 08:57:52 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:58:06 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:58:06 core-matter-server matter_server.server.client_handler[65] ERROR [547813051728] Error handling message: CommandMessage(message_id='7ba6d27ef0f54654ade14e1bbc6d1278', command='commission_on_network', args={'setup_pin_code': 61719140, 'ip_addr': None})
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/client_handler.py", line 188, in _run_handler
    result = await result
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 230, in commission_on_network
    raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission on network failed for node 23

In the log of my Matter device I can't find any Errors.

Is this a problem with the light switch or the Home Assistant? 

[Charlie]

Hi Vincent,

I doubt it is related to the sample itself since we normally test the samples on Apple and Google smart home ecosystems.

 (+) Matter: Testing the nRF Connect platform with Apple, Google and Samsung ecosystems - Blogs - Nordic Blog - Nordic DevZone (nordicsemi.com)

The Home Assistant log shows some errors are related to mDNS resolution timeout. Do you test in an office network environment? you need to pay attention to the router's mDNS setting.

Can you share the nRF Connect SDK version you are testing? Maybe you can enable more log information from the device and share it here. It would be helpful to understand the device's behaviour even if an error does not happen.

Best regards,

Charlie

[Vincent124]

Hi Charlie,

The mDNS Error was also there for the time the commissioning worked. I wasn't able to resolve this yet but it also wasn't a problem till now. I'll look into this too.

I'm using SDK verion 2.4.2.

For some reason I'm now getting the same Error for the light bulb too even though it worked just fine before. Here are some of the last few lines of the light bulb device log before the error occurs:

I: 90714 [ZCL]Commissioning window is now open
I: 90719 [EM]<<< [E:10474r S:23150 M:251748559 (Ack:124261149)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 90732 [IN](S) Sending msg 251748559 on secure session with LSID: 23150
I: 90765 [EM]>>> [E:10474r S:23150 M:124261150 (Ack:251748559)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 90832 [EM]>>> [E:10475r S:23150 M:124261151] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 90843 [IM]Received Read request
I: 90848 [EM]<<< [E:10475r S:23150 M:251748560 (Ack:124261151)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 90860 [IN](S) Sending msg 251748560 on secure session with LSID: 23150
I: 90897 [EM]>>> [E:10475r S:23150 M:124261152 (Ack:251748560)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 90914 [EM]>>> [E:10476r S:23150 M:124261153] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 90926 [EM]<<< [E:10476r S:23150 M:251748561 (Ack:124261153)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 90938 [IN](S) Sending msg 251748561 on secure session with LSID: 23150
I: 90968 [EM]>>> [E:10476r S:23150 M:124261154 (Ack:251748561)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 90981 [ZCL]Received command to close commissioning window
I: 90987 [SVR]Closing pairing window
D: 90990 [IN]SecureSession[0x20003320]: Released - Type:1 LSID:23152
I: 90996 [DIS]Updating services using commissioning mode 0
D: 91001 [DL]Using Thread extended MAC for hostname.
I: 91006 [DIS]Advertise operational node 310A9064FE4923E9-FCAA50B3BD23B59E
D: 91013 [DL]Using Thread extended MAC for hostname.
I: 91019 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 91029 [DL]advertising srp service: 592473A0AEB11410._matterc._udp
D: 91035 [DIS]Scheduling extended discovery timeout in 900s
I: 91040 [DL]removing srp service: FC0492C5D7C89E9C._matterc._udp
I: 91046 [ZCL]Commissioning window is now closed
I: 91051 [EM]<<< [E:10476r S:23150 M:251748562 (Ack:124261154)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 91064 [IN](S) Sending msg 251748562 on secure session with LSID: 23150
I: 91412 [EM]>>> [E:10476r S:23150 M:124261155 (Ack:251748562)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91429 [EM]>>> [E:10477r S:23150 M:124261156] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 91440 [IM]Received Read request
I: 91445 [EM]<<< [E:10477r S:23150 M:251748563 (Ack:124261156)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 91457 [IN](S) Sending msg 251748563 on secure session with LSID: 23150
I: 91497 [EM]>>> [E:10477r S:23150 M:124261157 (Ack:251748563)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91513 [EM]>>> [E:10478r S:23150 M:124261158] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 91524 [IM]Received Read request
I: 91529 [EM]<<< [E:10478r S:23150 M:251748564 (Ack:124261158)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 91541 [IN](S) Sending msg 251748564 on secure session with LSID: 23150
I: 91582 [EM]>>> [E:10478r S:23150 M:124261159 (Ack:251748564)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91598 [EM]>>> [E:10479r S:23150 M:124261160] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 91610 [EM]<<< [E:10479r S:23150 M:251748565 (Ack:124261160)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 91622 [IN](S) Sending msg 251748565 on secure session with LSID: 23150
I: 91680 [EM]>>> [E:10479r S:23150 M:124261161 (Ack:251748565)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 91694 [ZCL]Received command to open commissioning window
D: 91700 [IN]SecureSession[0x20003320]: Allocated Type:1 LSID:23153
I: 91706 [DIS]Updating services using commissioning mode 2
D: 91711 [DL]Using Thread extended MAC for hostname.
I: 91716 [DIS]Advertise operational node 310A9064FE4923E9-FCAA50B3BD23B59E
D: 91723 [DL]Using Thread extended MAC for hostname.
I: 91728 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3106/12 cm=2
I: 91738 [DL]advertising srp service: 77AD62A682F4EF64._matterc._udp
I: 91744 [DL]removing srp service: FC0492C5D7C89E9C._matterc._udp
I: 91750 [DL]removing srp service: 592473A0AEB11410._matterc._udp
I: 91756 [ZCL]Commissioning window is now open
I: 91761 [EM]<<< [E:10479r S:23150 M:251748566 (Ack:124261161)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 91774 [IN](S) Sending msg 251748566 on secure session with LSID: 23150
I: 91849 [EM]>>> [E:10479r S:23150 M:124261162 (Ack:251748566)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 92618 [DL]SRP update succeeded
E: 120209 [SWU]No suitable OTA Provider candidate found
I: 120214 [SWU]No provider available

I hope this is enough of the log, I'm not sure how much of it is important sorry!

Thanks in advance!

[Charlie]

Hi Vincent,

mDNS is used for bidirectional service discovery. Matter device commission would not work if the mDNS feature is disabled by your network.

I used to test in the office environment which blocks mDNS discovery, and the commission did not work. Switching to a home network or mobile phone WiFi host will solve the issue. Could you have a try?

Best regards,

Charlie

[Vincent124]

Hi Charlie,

I'm not working in a office environment and as I understand it, mDNS should be enabled in my network configuration, since I don't receive these many "ERROR Timeout waiting for mDNS resolution." Errors anymore. 

So the important logs form Matter Server Log state this:

2024-01-08 08:34:09 core-matter-server matter_server.server.device_controller[126] INFO Starting Matter commissioning on network using Node ID 5.
2024-01-08 08:34:39 core-matter-server chip.CTL[126] ERROR Mdns discovery timed out
2024-01-08 08:34:39 core-matter-server matter_server.server.client_handler[126] ERROR [548351953232] Error handling message: CommandMessage(message_id='afe520bcea0e4fdc8fcc09c8a1dd984d', command='commission_on_network', args={'setup_pin_code': 6859429, 'ip_addr': None})
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/client_handler.py", line 188, in _run_handler
    result = await result
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 261, in commission_on_network
    raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission on network failed for node 5

What I don't understand is why this only occurs when I use the light_switch. Adding another light_bulb is no problem

[Charlie]

so the current state is light_bulb is ok but light_swith has commissioning issue?

If yes, could you also share the log from the light_switch device?

[Vincent124]

Sure this is it: 

Fullscreen device_log.txt Download

I: Init CHIP stack
I: 221 [DL]BLE address: FB:6A:F9:87:9F:CA
I: 229 [DL]OpenThread SED interval is 1000ms
I: 235 [DL]OpenThread started: OK
I: 238 [DL]Setting OpenThread device type to SLEEPY END DEVICE
I: 244 [SVR]Subscription persistence not supported
I: 248 [SVR]Server initializing...
I: 251 [TS]Last Known Good Time: [unknown]
I: 255 [TS]Setting Last Known Good Time to firmware build time 2024-01-04T16:30:27
I: 267 [DMG]AccessControl: initializing
I: 270 [DMG]Examples::AccessControlDelegate::Init
I: 275 [DMG]AccessControl: setting
I: 278 [DMG]DefaultAclStorage: initializing
I: 282 [DMG]DefaultAclStorage: 0 entries loaded
D: 286 [IN]UDP::Init bind&listen port=5540
E: 290 [IN]SO_REUSEPORT failed: 109
D: 294 [IN]UDP::Init bound to port=5540
D: 297 [IN]BLEBase::Init - setting/overriding transport
D: 302 [IN]TransportMgr initialized
D: 313 [DL]Using Thread extended MAC for hostname.
I: 323 [ZCL]Using ZAP configuration...
I: 327 [DMG]AccessControlCluster: initializing
D: 331 [DL]Boot reason: 1
I: 334 [ZCL]Initiating Admin Commissioning cluster.
I: 339 [DIS]Updating services using commissioning mode 0
E: 344 [DIS]Failed to remove advertised services: 3
D: 348 [DL]Using Thread extended MAC for hostname.
I: 353 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
E: 362 [DIS]Failed to advertise extended commissionable node: 3
D: 368 [DIS]Scheduling extended discovery timeout in 900s
E: 373 [DIS]Failed to finalize service update: 3
I: 377 [DIS]Delaying proxy of operational discovery: missing delegate
I: 384 [IN]CASE Server enabling CASE session setups
D: 389 [IN]SecureSession[0x200033b8]: Allocated Type:2 LSID:25936
I: 394 [SVR]Joining Multicast groups
I: 398 [SVR]Server Listening...
I: 401 [DL]Device Configuration:
I: 404 [DL]  Serial Number: 11223344556677889900
I: 408 [DL]  Vendor Id: 65521 (0xFFF1)
I: 412 [DL]  Product Id: 32772 (0x8004)
I: 415 [DL]  Product Name: not-specified
I: 419 [DL]  Hardware Version: 0
I: 422 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 428 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 434 [DL]  Manufacturing Date: (not set)
I: 438 [DL]  Device Type: 65535 (0xFFFF)
I: 442 [SVR]SetupQRCode: [MT:4CT9142C00KA0648G00]
I: 447 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 453 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A4CT9142C00KA0648G00
I: 462 [SVR]Manual pairing code: [34970112332]
I: 467 [DL]CHIP task running
I: 470 [DIS]Updating services using commissioning mode 0
E: 475 [DIS]Failed to remove advertised services: 3
D: 480 [DL]Using Thread extended MAC for hostname.
I: 485 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
E: 493 [DIS]Failed to advertise extended commissionable node: 3
E: 499 [DIS]Failed to finalize service update: 3
I: Initialize binding Handler
I: 506 [SVR]Cannot load binding table: a0
I: Binding Table size: [0]:
I: 4951 [DL]OpenThread SED interval is 200ms
D: 4956 [IN]SecureSession[0x20003470]: Allocated Type:1 LSID:25937
D: 4962 [DL]CHIPoBLE advertising set to on
I: 4966 [DIS]Updating services using commissioning mode 1
E: 4971 [DIS]Failed to remove advertised services: 3
D: 4976 [DL]Using Thread extended MAC for hostname.
I: 4981 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=1
E: 4990 [DIS]Failed to advertise commissionable node: 3
E: 4995 [DIS]Failed to finalize service update: 3
I: 5001 [DL]CHIPoBLE advertising started
I: 5005 [DL]NFC Tag emulation started
I: 35005 [DL]CHIPoBLE advertising mode changed to slow
I: 35011 [DL]CHIPoBLE advertising started
I: 45581 [DL]BLE connection established (ConnId: 0x00)
I: 45586 [DL]Current number of connections: 1/1
I: 45590 [DL]CHIPoBLE advertising stopped
I: 45594 [DL]NFC Tag emulation stopped
D: 46284 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 46291 [BLE]local and remote recv window sizes = 5
I: 46296 [BLE]selected BTP version 4
I: 46300 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 46307 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 46311 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 46319 [IN]BLE EndPoint 0x2000fc30 Connection Complete
I: 46324 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 46404 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46494 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 46502 [EM]>>> [E:32766r S:0 M:170198130] (U) Msg RX from 0:966F48DB880EF1EA [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 46515 [EM]<<< [E:32766r S:0 M:7730617] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 46527 [IN](U) Sending msg 7730617 to IP address 'BLE'
D: 46532 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 46584 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46592 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 46674 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46682 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 46690 [EM]>>> [E:32766r S:0 M:170198131] (U) Msg RX from 0:966F48DB880EF1EA [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 48446 [EM]<<< [E:32766r S:0 M:7730618] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 48458 [IN](U) Sending msg 7730618 to IP address 'BLE'
D: 48463 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
E: 48471 [DL]Long dispatch time: 1789 ms, for event type 16388
D: 48549 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48557 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 48640 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48647 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 48655 [EM]>>> [E:32766r S:0 M:170198132] (U) Msg RX from 0:966F48DB880EF1EA [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 48667 [EM]<<< [E:32766r S:0 M:7730619] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 48678 [IN](U) Sending msg 7730619 to IP address 'BLE'
D: 48684 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 48692 [SC]SecureSession[0x20003470]: Moving from state 'kEstablishing' --> 'kActive'
D: 48700 [IN]SecureSession[0x20003470]: Activated - Type:1 LSID:25937
D: 48706 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:25937 PSID:28442!
I: 48715 [SVR]Commissioning completed session establishment step
I: 48721 [DIS]Updating services using commissioning mode 0
E: 48726 [DIS]Failed to remove advertised services: 3
D: 48732 [DL]Using Thread extended MAC for hostname.
I: 48737 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
E: 48746 [DIS]Failed to advertise extended commissionable node: 3
D: 48752 [DIS]Scheduling extended discovery timeout in 900s
E: 48757 [DIS]Failed to finalize service update: 3
D: 48761 [DL]CHIPoBLE advertising set to off
I: 48766 [SVR]Device completed Rendezvous process
E: 48770 [DL]Long dispatch time: 123 ms, for event type 16388
D: 48777 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48784 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 48792 [EM]>>> [E:32767r S:25937 M:251125488] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 48803 [IM]Received Read request
I: 48809 [EM]<<< [E:32767r S:25937 M:266401165] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 48819 [IN](S) Sending msg 266401165 on secure session with LSID: 25937
D: 48826 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 97)
D: 48910 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48917 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 48925 [EM]>>> [E:32768r S:25937 M:251125489] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 48936 [IM]Received Read request
I: 48941 [EM]<<< [E:32768r S:25937 M:266401166] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 48952 [IN](S) Sending msg 266401166 on secure session with LSID: 25937
D: 48959 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 49045 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49052 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49060 [EM]>>> [E:32769r S:25937 M:251125490] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49071 [IM]Received Read request
I: 49076 [EM]<<< [E:32769r S:25937 M:266401167] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49087 [IN](S) Sending msg 266401167 on secure session with LSID: 25937
D: 49094 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 49180 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49187 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49195 [EM]>>> [E:32770r S:25937 M:251125491] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49206 [IM]Received Read request
I: 49211 [EM]<<< [E:32770r S:25937 M:266401168] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49222 [IN](S) Sending msg 266401168 on secure session with LSID: 25937
D: 49229 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 49315 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49322 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49330 [EM]>>> [E:32771r S:25937 M:251125492] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49341 [IM]Received Read request
I: 49346 [EM]<<< [E:32771r S:25937 M:266401169] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49357 [IN](S) Sending msg 266401169 on secure session with LSID: 25937
D: 49364 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 49450 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49457 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49465 [EM]>>> [E:32772r S:25937 M:251125493] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49476 [IM]Received Read request
I: 49481 [EM]<<< [E:32772r S:25937 M:266401170] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49492 [IN](S) Sending msg 266401170 on secure session with LSID: 25937
D: 49499 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 49585 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49592 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49600 [EM]>>> [E:32773r S:25937 M:251125494] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49611 [IM]Received Read request
I: 49617 [EM]<<< [E:32773r S:25937 M:266401171] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49627 [IN](S) Sending msg 266401171 on secure session with LSID: 25937
D: 49634 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 97)
D: 49720 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49727 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49735 [EM]>>> [E:32774r S:25937 M:251125495] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49746 [IM]Received Read request
I: 49751 [EM]<<< [E:32774r S:25937 M:266401172] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49762 [IN](S) Sending msg 266401172 on secure session with LSID: 25937
D: 49769 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 49855 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49862 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49870 [EM]>>> [E:32775r S:25937 M:251125496] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 49881 [IM]Received Read request
I: 49886 [EM]<<< [E:32775r S:25937 M:266401173] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 49897 [IN](S) Sending msg 266401173 on secure session with LSID: 25937
D: 49904 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 49989 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 52509 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 55017 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 55074 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 57594 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 59889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 59897 [EM]>>> [E:32776r S:25937 M:251125497] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
I: 59909 [EM]<<< [E:32776r S:25937 M:266401174] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 59920 [IN](S) Sending msg 266401174 on secure session with LSID: 25937
D: 59926 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 60024 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60032 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60040 [EM]>>> [E:32776r S:25937 M:251125498] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 60052 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 60059 [EM]<<< [E:32776r S:25937 M:266401175] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 60071 [IN](S) Sending msg 266401175 on secure session with LSID: 25937
D: 60078 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 60159 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60167 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60175 [EM]>>> [E:32777r S:25937 M:251125499] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 60186 [IM]Received Read request
I: 60191 [EM]<<< [E:32777r S:25937 M:266401176] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 60202 [IN](S) Sending msg 266401176 on secure session with LSID: 25937
D: 60208 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 60294 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60302 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60310 [EM]>>> [E:32778r S:25937 M:251125500] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
I: 60322 [EM]<<< [E:32778r S:25937 M:266401177] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 60333 [IN](S) Sending msg 266401177 on secure session with LSID: 25937
D: 60340 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 60429 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60437 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60445 [EM]>>> [E:32778r S:25937 M:251125501] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 60476 [EM]<<< [E:32778r S:25937 M:266401178] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 60488 [IN](S) Sending msg 266401178 on secure session with LSID: 25937
D: 60495 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 60609 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60617 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60625 [EM]>>> [E:32779r S:25937 M:251125502] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 60637 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 60647 [EM]<<< [E:32779r S:25937 M:266401179] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 60658 [IN](S) Sending msg 266401179 on secure session with LSID: 25937
D: 60665 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 60744 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60752 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 60834 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60841 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 60924 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60931 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61014 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61022 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 61029 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 58)
D: 61104 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61112 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61120 [EM]>>> [E:32780r S:25937 M:251125503] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 61132 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 61141 [EM]<<< [E:32780r S:25937 M:266401180] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 61153 [IN](S) Sending msg 266401180 on secure session with LSID: 25937
D: 61160 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61239 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61246 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61329 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61336 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61419 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61426 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61509 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61517 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 61524 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28)
D: 61599 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61607 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61615 [EM]>>> [E:32781r S:25937 M:251125504] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 61627 [ZCL]OpCreds: Received an AttestationRequest command
I: 61667 [ZCL]OpCreds: AttestationRequest successful.
I: 61675 [EM]<<< [E:32781r S:25937 M:266401181] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 61687 [IN](S) Sending msg 266401181 on secure session with LSID: 25937
D: 61694 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61779 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61786 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61869 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61876 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 61959 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61966 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62049 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62094 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 62101 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62184 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62191 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90)
D: 62274 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62282 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 62290 [EM]>>> [E:32782r S:25937 M:251125505] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 62302 [ZCL]OpCreds: Received a CSRRequest command
I: 62485 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 62524 [ZCL]OpCreds: CSRRequest successful.
I: 62530 [EM]<<< [E:32782r S:25937 M:266401182] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 62542 [IN](S) Sending msg 266401182 on secure session with LSID: 25937
D: 62549 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
E: 62556 [DL]Long dispatch time: 274 ms, for event type 16388
D: 62634 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62641 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62724 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62731 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62814 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63759 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 63849 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 63939 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63948 [EM]>>> [E:32783r S:25937 M:251125506] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 63960 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 64029 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 64036 [EM]<<< [E:32783r S:25937 M:266401183] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 64048 [IN](S) Sending msg 266401183 on secure session with LSID: 25937
D: 64054 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
E: 64062 [DL]Long dispatch time: 123 ms, for event type 16388
D: 64119 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64127 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64209 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64299 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64434 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64441 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
I: 64451 [EM]>>> [E:32784r S:25937 M:251125507] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 64463 [ZCL]OpCreds: Received an AddNOC command
I: 64470 [FP]Validating NOC chain
I: 64537 [FP]NOC chain validation successful
I: 64541 [FP]Added new fabric at index: 0x1
I: 64545 [FP]Assigned compressed fabric ID: 0x310A9064FE4923E9, node ID: 0x3992EA419D6B939E
I: 64553 [TS]Last Known Good Time: 2024-01-04T16:30:27
I: 64558 [TS]New proposed Last Known Good Time: 2024-01-01T00:00:00
I: 64564 [TS]Retaining current Last Known Good Time
I: 64592 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
D: 64601 [DL]Using Thread extended MAC for hostname.
I: 64606 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
I: 64613 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 64620 [EM]<<< [E:32784r S:25937 M:266401184] (S) Msg TX to 1:FFFFFFFB00000000 [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 64632 [IN](S) Sending msg 266401184 on secure session with LSID: 25937
E: 64638 [DL]Long dispatch time: 204 ms, for event type 16388
D: 64644 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64652 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 64748 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64757 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64884 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 64893 [EM]>>> [E:32785r S:25937 M:251125508] (S) Msg RX from 1:FFFFFFFB00000000 [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 64911 [EM]<<< [E:32785r S:25937 M:266401185] (S) Msg TX to 1:FFFFFFFB00000000 [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 64923 [IN](S) Sending msg 266401185 on secure session with LSID: 25937
D: 64930 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 65019 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65027 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 65035 [EM]>>> [E:32786r S:25937 M:251125509] (S) Msg RX from 1:FFFFFFFB00000000 [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 65046 [IM]Received Read request
I: 65051 [EM]<<< [E:32786r S:25937 M:266401186] (S) Msg TX to 1:FFFFFFFB00000000 [23E9] --- Type 0001:05 (IM:ReportData)
I: 65062 [IN](S) Sending msg 266401186 on secure session with LSID: 25937
D: 65068 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 65154 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65162 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 65170 [EM]>>> [E:32787r S:25937 M:251125510] (S) Msg RX from 1:FFFFFFFB00000000 [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 65193 [DL]OpenThread State Changed (Flags: 0x1017c100)
D: 65198 [DL]   Network Name: OpenThreadDemo
D: 65202 [DL]   PAN Id: 0x1234
D: 65205 [DL]   Extended PAN Id: 0x1111111122222222
D: 65210 [DL]   Channel: 15
D: 65212 [DL]   Mesh Prefix: fd30:7a52:371e:f565::/64
D: 65218 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 65223 [DL]   Device Role: DETACHED
D: 65227 [DL]   Thread Unicast Addresses:
D: 65230 [DL]        fd30:7a52:371e:f565:ec2b:b609:669d:4420/64 valid
D: 65237 [DL]        fe80::4856:c567:6040:899c/64 valid preferred
I: 66598 [DL]SRP Client was started, detected server: fd30:7a52:371e:f565:58a2:925e:b943:7c56
D: 66608 [DL]OpenThread State Changed (Flags: 0x200002a4)
D: 66613 [DL]   Device Role: CHILD
D: 66616 [DL]   Partition Id: 0x77BB2A4B
D: 66621 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 66626 [DL]   Thread Unicast Addresses:
D: 66630 [DL]        fd79:7f72:32f0:1:2148:587f:2d26:c6d3/64 valid preferred
D: 66636 [DL]        fd30:7a52:371e:f565:0:ff:fe00:a404/64 valid rloc
D: 66643 [DL]        fd30:7a52:371e:f565:ec2b:b609:669d:4420/64 valid
D: 66649 [DL]        fe80::4856:c567:6040:899c/64 valid preferred
I: 66657 [EM]<<< [E:32787r S:25937 M:266401187] (S) Msg TX to 1:FFFFFFFB00000000 [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 66668 [IN](S) Sending msg 266401187 on secure session with LSID: 25937
D: 66675 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 66683 [DL]Using Thread extended MAC for hostname.
I: 66688 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
I: 66694 [SVR]Operational advertising enabled
D: 66729 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67352 [DL]SRP update succeeded
I: 67356 [DIS]Setting operational delegate post init
I: 67364 [SWU]Stopping the watchdog timer
I: 67367 [SWU]Starting the periodic query timer, timeout: 86400 seconds
E: 67374 [SVR]Server initialization complete
I: 67378 [DIS]Updating services using commissioning mode 0
D: 67383 [DL]Using Thread extended MAC for hostname.
I: 67388 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
I: 67395 [DL]advertising srp service: 310A9064FE4923E9-3992EA419D6B939E._matter._tcp
D: 67402 [DL]Using Thread extended MAC for hostname.
I: 67408 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
I: 67417 [DL]advertising srp service: C2BA875DA65835CF._matterc._udp
I: 67764 [DL]BLE GAP connection terminated (reason 0x13)
I: 67769 [DL]Current number of connections: 0/1
D: 68706 [DL]SRP update succeeded
I: 69121 [EM]>>> [E:32788r S:0 M:170198133] (U) Msg RX from 0:166194B2E5EC28ED [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 69133 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004d78
I: 69140 [IN]CASE Server disabling CASE session setups
I: 69146 [EM]<<< [E:32788r S:0 M:7730620 (Ack:170198133)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 69158 [IN](U) Sending msg 7730620 to IP address 'UDP:[fd11:1111:1122:2222:58e:9527:da88:956e]:48281'
I: 69169 [SC]Received Sigma1 msg
I: 69176 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x3992EA419D6B939E
I: 69391 [EM]<<< [E:32788r S:0 M:7730621 (Ack:170198133)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 69404 [IN](U) Sending msg 7730621 to IP address 'UDP:[fd11:1111:1122:2222:58e:9527:da88:956e]:48281'
I: 69415 [SC]Sent Sigma2 msg
I: 70104 [EM]>>> [E:32788r S:0 M:170198134 (Ack:7730621)] (U) Msg RX from 0:166194B2E5EC28ED [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 70117 [EM]<<< [E:32788r S:0 M:7730622 (Ack:170198134)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 70130 [IN](U) Sending msg 7730622 to IP address 'UDP:[fd11:1111:1122:2222:58e:9527:da88:956e]:48281'
I: 70140 [SC]Received Sigma3 msg
E: 70148 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 70282 [DL]Long dispatch time: 124 ms, for event type 2
I: 70310 [EM]<<< [E:32788r S:0 M:7730623 (Ack:170198134)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 70323 [IN](U) Sending msg 7730623 to IP address 'UDP:[fd11:1111:1122:2222:58e:9527:da88:956e]:48281'
I: 70335 [SC]SecureSession[0x200033b8]: Moving from state 'kEstablishing' --> 'kActive'
D: 70343 [IN]SecureSession[0x200033b8]: Activated - Type:2 LSID:25936
D: 70349 [IN]New secure session activated for device <D07881E73455012C, 1>, LSID:25936 PSID:28443!
I: 70358 [IN]CASE Session established to peer: <D07881E73455012C, 1>
I: 70364 [IN]CASE Server enabling CASE session setups
D: 70369 [IN]SecureSession[0x20003528]: Allocated Type:2 LSID:25938
I: 70506 [EM]>>> [E:32788r S:0 M:170198135 (Ack:7730623)] (U) Msg RX from 0:166194B2E5EC28ED [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 70531 [EM]>>> [E:32789r S:25936 M:256249412] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 70542 [IM]Received Read request
I: 70547 [EM]<<< [E:32789r S:25936 M:839296 (Ack:256249412)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 70559 [IN](S) Sending msg 839296 on secure session with LSID: 25936
I: 70918 [EM]>>> [E:32789r S:25936 M:256249413 (Ack:839296)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 70942 [EM]>>> [E:32790r S:25936 M:256249414] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 70953 [IM]Received Read request
I: 70959 [EM]<<< [E:32790r S:25936 M:839297 (Ack:256249414)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 70970 [IN](S) Sending msg 839297 on secure session with LSID: 25936
I: 71328 [EM]>>> [E:32790r S:25936 M:256249415 (Ack:839297)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 71354 [EM]>>> [E:32791r S:25936 M:256249416] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 71366 [FS]GeneralCommissioning: Received CommissioningComplete
I: 71381 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 71409 [TS]Committing Last Known Good Time to storage: 2024-01-04T16:30:27
I: 71421 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x310A9064FE4923E9, FabricId D145FFFDE1A6BB37, NodeId 3992EA419D6B939E, VendorId 0x6006
I: 71438 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 71445 [FS]Fail-safe cleanly disarmed
I: 71450 [EM]<<< [E:32791r S:25936 M:839298 (Ack:256249416)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 71462 [IN](S) Sending msg 839298 on secure session with LSID: 25936
I: 71470 [SWU]Device commissioned, schedule a default provider query
I: 71477 [SVR]Commissioning completed successfully
I: 71482 [DIS]Updating services using commissioning mode 0
D: 71487 [DL]Using Thread extended MAC for hostname.
I: 71492 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
D: 71499 [DL]Using Thread extended MAC for hostname.
I: 71504 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
D: 71514 [IN]Expiring all PASE sessions
D: 71518 [IN]SecureSession[0x20003470]: MarkForEviction Type:1 LSID:25937
I: 71524 [SC]SecureSession[0x20003470]: Moving from state 'kActive' --> 'kPendingEviction'
D: 71533 [IN]SecureSession[0x20003470]: Released - Type:1 LSID:25937
D: 71540 [IN]Clearing BLE pending packets.
I: 71544 [BLE]Releasing end point's BLE connection back to application.
I: 71550 [DL]Closing BLE GATT connection (ConnId 00)
I: 71743 [EM]>>> [E:32791r S:25936 M:256249417 (Ack:839298)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 71758 [DL]OpenThread SED interval is 1000ms
I: 71763 [EM]>>> [E:32792r S:25936 M:256249418] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 71774 [IM]Received Read request
I: 71778 [DL]OpenThread SED interval is 200ms
I: 71784 [EM]<<< [E:32792r S:25936 M:839299 (Ack:256249418)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 71795 [IN](S) Sending msg 839299 on secure session with LSID: 25936
I: 71953 [EM]>>> [E:32792r S:25936 M:256249419 (Ack:839299)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 71969 [DL]OpenThread SED interval is 1000ms
I: 71974 [EM]>>> [E:32793r S:25936 M:256249420] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 71985 [IM]Received Read request
I: 71989 [DL]OpenThread SED interval is 200ms
I: 71994 [EM]<<< [E:32793r S:25936 M:839300 (Ack:256249420)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 72006 [IN](S) Sending msg 839300 on secure session with LSID: 25936
I: 72269 [EM]>>> [E:32793r S:25936 M:256249421 (Ack:839300)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 72282 [DL]OpenThread SED interval is 1000ms
I: 72399 [EM]>>> [E:32794r S:25936 M:256249422] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 72410 [IM]Received Read request
I: 72414 [DL]OpenThread SED interval is 200ms
I: 72419 [EM]<<< [E:32794r S:25936 M:839301 (Ack:256249422)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 72431 [IN](S) Sending msg 839301 on secure session with LSID: 25936
I: 72802 [EM]>>> [E:32794r S:25936 M:256249423 (Ack:839301)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 72818 [DL]OpenThread SED interval is 1000ms
I: 72823 [EM]>>> [E:32795r S:25936 M:256249424] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 72835 [EM]<<< [E:32795r S:25936 M:839302 (Ack:256249424)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 72847 [IN](S) Sending msg 839302 on secure session with LSID: 25936
I: 72855 [DL]OpenThread SED interval is 200ms
I: 73236 [EM]>>> [E:32795r S:25936 M:256249425 (Ack:839302)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 73249 [ZCL]Received command to open commissioning window
D: 73255 [IN]SecureSession[0x20003470]: Allocated Type:1 LSID:25939
I: 73261 [DIS]Updating services using commissioning mode 2
D: 73266 [DL]Using Thread extended MAC for hostname.
I: 73271 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
D: 73278 [DL]Using Thread extended MAC for hostname.
I: 73284 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3468/13 cm=2
I: 73293 [DL]advertising srp service: 2A825572D051D4B4._matterc._udp
I: 73300 [DL]removing srp service: C2BA875DA65835CF._matterc._udp
I: 73305 [ZCL]Commissioning window is now open
I: 73311 [EM]<<< [E:32795r S:25936 M:839303 (Ack:256249425)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 73324 [IN](S) Sending msg 839303 on secure session with LSID: 25936
I: 73610 [EM]>>> [E:32795r S:25936 M:256249426 (Ack:839303)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 73634 [EM]>>> [E:32796r S:25936 M:256249427] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 73645 [IM]Received Read request
I: 73650 [EM]<<< [E:32796r S:25936 M:839304 (Ack:256249427)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 73662 [IN](S) Sending msg 839304 on secure session with LSID: 25936
I: 73997 [EM]>>> [E:32796r S:25936 M:256249428 (Ack:839304)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 74021 [EM]>>> [E:32797r S:25936 M:256249429] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 74033 [EM]<<< [E:32797r S:25936 M:839305 (Ack:256249429)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 74045 [IN](S) Sending msg 839305 on secure session with LSID: 25936
I: 74195 [EM]>>> [E:32797r S:25936 M:256249430 (Ack:839305)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 74209 [ZCL]Received command to close commissioning window
I: 74214 [SVR]Closing pairing window
D: 74218 [IN]SecureSession[0x20003470]: Released - Type:1 LSID:25939
I: 74224 [DIS]Updating services using commissioning mode 0
D: 74229 [DL]Using Thread extended MAC for hostname.
I: 74234 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
D: 74241 [DL]Using Thread extended MAC for hostname.
I: 74246 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3840/15 cm=0
I: 74256 [DL]advertising srp service: 2A825572D051D4B4._matterc._udp
D: 74262 [DIS]Scheduling extended discovery timeout in 900s
I: 74268 [DL]removing srp service: C2BA875DA65835CF._matterc._udp
I: 74273 [ZCL]Commissioning window is now closed
I: 74279 [EM]<<< [E:32797r S:25936 M:839306 (Ack:256249430)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 74292 [IN](S) Sending msg 839306 on secure session with LSID: 25936
I: 74893 [EM]>>> [E:32797r S:25936 M:256249431 (Ack:839306)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 74907 [DL]OpenThread SED interval is 1000ms
I: 74923 [EM]>>> [E:32798r S:25936 M:256249432] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 74935 [IM]Received Read request
I: 74940 [DL]OpenThread SED interval is 200ms
I: 74945 [EM]<<< [E:32798r S:25936 M:839307 (Ack:256249432)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 74957 [IN](S) Sending msg 839307 on secure session with LSID: 25936
I: 75296 [EM]>>> [E:32799r S:25936 M:256249433] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 75309 [IM]Received Read request
I: 75314 [EM]<<< [E:32799r S:25936 M:839308 (Ack:256249433)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 75326 [IN](S) Sending msg 839308 on secure session with LSID: 25936
I: 75335 [EM]>>> [E:32798r S:25936 M:256249434 (Ack:839307)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 75494 [EM]>>> [E:32799r S:25936 M:256249435 (Ack:839308)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 75509 [DL]OpenThread SED interval is 1000ms
I: 75515 [EM]>>> [E:32800r S:25936 M:256249436] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 75527 [EM]<<< [E:32800r S:25936 M:839309 (Ack:256249436)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 75539 [IN](S) Sending msg 839309 on secure session with LSID: 25936
I: 75547 [DL]OpenThread SED interval is 200ms
I: 75718 [EM]>>> [E:32800r S:25936 M:256249437 (Ack:839309)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 75732 [ZCL]Received command to open commissioning window
D: 75738 [IN]SecureSession[0x20003470]: Allocated Type:1 LSID:25940
I: 75744 [DIS]Updating services using commissioning mode 2
D: 75749 [DL]Using Thread extended MAC for hostname.
I: 75754 [DIS]Advertise operational node 310A9064FE4923E9-3992EA419D6B939E
D: 75761 [DL]Using Thread extended MAC for hostname.
I: 75766 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=1466/05 cm=2
I: 75776 [DL]advertising srp service: DEBE6C323524D155._matterc._udp
I: 75782 [DL]removing srp service: C2BA875DA65835CF._matterc._udp
I: 75788 [DL]removing srp service: 2A825572D051D4B4._matterc._udp
I: 75794 [ZCL]Commissioning window is now open
I: 75799 [EM]<<< [E:32800r S:25936 M:839310 (Ack:256249437)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 75812 [IN](S) Sending msg 839310 on secure session with LSID: 25936
I: 76522 [EM]>>> [E:32800r S:25936 M:256249438 (Ack:839310)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 77083 [DL]SRP update succeeded
E: 101477 [SWU]No suitable OTA Provider candidate found
I: 101482 [SWU]No provider available

[Charlie]

Do the two logs from the same try?

From the Matter server log I can see that the device has not been discovered by the Home Assistant ecosystem, but the logs from the device show that there was connection to the ecosystem app established successfully:

I: 71470 [SWU]Device commissioned, schedule a default provider query
I: 71477 [SVR]Commissioning completed successfully

Then there are some strange logs in the device log, that there were some tries to "open commissioning window" so the device prepared itself for the commissioning to the next ecosystem:

I: 73249 [ZCL]Received command to open commissioning window

I guess that this command comes from the ecosystem app.

Honestly we don't test any devices with HomeAssistant.io, so we don't know how it works. Could you also generate an issue here to check with Home Assistant team about this issue? Issues · home-assistant/core · GitHub

The light switch sample uses Dimmable Light Switch Matter device type. It is not clear if this device type is supported by the Home Assistant ecosystem. Please be realized the Matter integration of Home Assistant is still in beta stage. Matter (BETA) - Home Assistant (home-assistant.io)

Best regards,

Charlie