Matter Binding after disconnecting OTBR

[jayveer]

I am working on Matter binding between two matter enabled thread devices where i have flashed the light bulb code in EVBT840 and light switch in nrf52840 kit

I am using Raspberry pi 4B as OTBR and commissioning is done using chip tool in linux pc. After commissioning both the devices in thread network and matter binding is done between both the device is done where when i press the switch in matter switch the matter bulb glows. So after the matter binding between both the matter devices when i disconnect the OTBR the communication between them till remain for around 2 mins where without OTBR i can control bulb with switch but after that the connection breaks.

So once commissioned and matter binded ,then removing the OTBR should the connection between them still remain or there is issue with my ecosystem ?

[Charlie]

Hi Jayveer,

Sorry for the late reply. We are short on staff due to summer vacation.

Currently, it is not possible to control Thread devices over Matter devices without Border Router. The Border Router is an SRP server which is needed for devices to be able to resolve other devices over matter.
Additionally, while the border router is removed the Thread devices remove external IP address which is in use during Matter communication. The Thread topology is recreated and if the light bulb is Thread FTD device then it start to be a leader in Thread topology.

In your case, I have no control over what firmware the EVBT840 is running, however, if the device (as light bulb) is not an FTD Thread device then without Border Router the devices cannot re-create Thread network due to lack of leader capable device. The Nordic Sample of Light Switch is MTD Thread device. There must be an SRP server in the Thread network to let Matter devices discover each other's IP addresses. This doesn't have to be a border router, it can be any Thread router that enables the SRP server functionality though.

Best regards,

Charlie

[jayveer]

Thank you so much Charlie ,

Your answer would really be helpful for us.

We are flashing the Nordic sample of Light bulb in EVBT840.So will it be FTD thread device ?

[Charlie]

Yes, the Light bulb runs as an FTD router.

[jayveer]

ok so we are flashing the Nordic sample Light bulb in nrf52840 and Light switch in EVBT840 . So as the Light bulb is FTD , after removing the OTBR it has to became the leader and recreate the thread topology but it is not happening. The light bulb is not able to became the leader and the connection between the switch and bulb breaks after 2 mins of removing the OTBR , so according to you what could be issue, could it be of build configuration one ?

Best Regards,

Jayveer

[Charlie]

Hi Jayverr,

Can you share the log files from light bulb and switch devices?

Best regards,

Charlie

[jayveer]

Yes Charlie , here are the logs of light switch and light bulb

Fullscreen light switch logs.txt Download

214104 [DMG]Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
D: Binding command applied successfully!
I: 214118 [DL]OpenThread SED interval is 1000ms
I: 214123 [EM]<<< [E:20084i M:101059279 (Ack:138837795)] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 214135 [IN](S) Sending msg 101059279 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 216152 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 216159 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 216167 [EM]<<< [E:20085i M:101059280] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 216178 [IN](S) Sending msg 101059280 on secure session with LSID: 48652
I: 216186 [DL]OpenThread SED interval is 200ms
I: 216493 [EM]>>> [E:20085i M:138837796 (Ack:101059280)] (S) Msg RX from 1:0000000000000078 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 216506 [DMG]Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
D: Binding command applied successfully!
I: 216520 [DL]OpenThread SED interval is 1000ms
I: 216525 [EM]<<< [E:20085i M:101059281 (Ack:138837796)] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 216538 [IN](S) Sending msg 101059281 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 218306 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 218312 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 218321 [EM]<<< [E:20086i M:101059282] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 218332 [IN](S) Sending msg 101059282 on secure session with LSID: 48652
I: 218340 [DL]OpenThread SED interval is 200ms
I: 218564 [EM]>>> [E:20086i M:138837797 (Ack:101059282)] (S) Msg RX from 1:0000000000000078 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 218577 [DMG]Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
D: Binding command applied successfully!
I: 218591 [DL]OpenThread SED interval is 1000ms
I: 218596 [EM]<<< [E:20086i M:101059283 (Ack:138837797)] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 218609 [IN](S) Sending msg 101059283 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 282355 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 282362 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 282370 [EM]<<< [E:20087i M:101059284] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 282381 [IN](S) Sending msg 101059284 on secure session with LSID: 48652
I: 282389 [DL]OpenThread SED interval is 200ms
I: 282613 [EM]>>> [E:20087i M:138837798 (Ack:101059284)] (S) Msg RX from 1:0000000000000078 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 282627 [DMG]Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
D: Binding command applied successfully!
I: 282641 [DL]OpenThread SED interval is 1000ms
I: 282646 [EM]<<< [E:20087i M:101059285 (Ack:138837798)] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 282658 [IN](S) Sending msg 101059285 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 322844 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 322850 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 322858 [EM]<<< [E:20088i M:101059286] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 322869 [IN](S) Sending msg 101059286 on secure session with LSID: 48652
I: 322878 [DL]OpenThread SED interval is 200ms
I: 323101 [EM]>>> [E:20088i M:138837799 (Ack:101059286)] (S) Msg RX from 1:0000000000000078 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 323114 [DMG]Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
D: Binding command applied successfully!
I: 323128 [DL]OpenThread SED interval is 1000ms
I: 323133 [EM]<<< [E:20088i M:101059287 (Ack:138837799)] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 323146 [IN](S) Sending msg 101059287 on secure session with LSID: 48652
I: 384106 [DL]SRP Client was stopped, because current server is no longer detected.
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 401172 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 401178 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 401186 [EM]<<< [E:20089i M:101059288] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 401197 [IN](S) Sending msg 101059288 on secure session with LSID: 48652
I: 401205 [DL]OpenThread SED interval is 200ms
I: 403126 [IN](S) Sending msg 101059288 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 404438 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 404445 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 404453 [EM]<<< [E:20090i M:101059289] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 404464 [IN](S) Sending msg 101059289 on secure session with LSID: 48652
I: 405019 [IN](S) Sending msg 101059288 on secure session with LSID: 48652
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 405582 [CTL]Found an existing secure session to [1:0000000000000078]!
D: 405589 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 5
I: 405597 [EM]<<< [E:20091i M:101059290] (S) Msg TX to 1:0000000000000078 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 405608 [IN](S) Sending msg 101059290 on secure session with LSID: 48652
I: 406400 [IN](S) Sending msg 101059289 on secure session with LSID: 48652
I: 407582 [IN](S) Sending msg 101059290 on secure session with LSID: 48652
I: 407633 [IN](S) Sending msg 101059288 on secure session with LSID: 48652
I: 408430 [IN](S) Sending msg 101059289 on secure session with LSID: 48652
I: 409528 [IN](S) Sending msg 101059290 on secure session with LSID: 48652
I: 411239 [IN](S) Sending msg 101059289 on secure session with LSID: 48652
I: 411669 [IN](S) Sending msg 101059288 on secure session with LSID: 48652
I: 412168 [IN](S) Sending msg 101059290 on secure session with LSID: 48652
I: 414782 [IN](S) Sending msg 101059289 on secure session with LSID: 48652
I: 415943 [IN](S) Sending msg 101059290 on secure session with LSID: 48652
E: 417230 [EM]Failed to Send CHIP MessageCounter:101059288 on exchange 20089i sendCount: 4 max retries: 4
D: 420773 [IN]SecureSession[0x200037e0]: MarkAsDefunct Type:2 LSID:48652
I: 420780 [SC]SecureSession[0x200037e0]: Moving from state 'kActive' --> 'kDefunct'
I: 420787 [DMG]Time out! failed to receive invoke command response from Exchange: 20089i
I: Response timeout for invoked command, trying to recover CASE session.
D: 420802 [CTL]OperationalSessionSetup[1:0000000000000078]: State change 1 --> 2
I: 420809 [DIS]Resolving 627F117C2336D7CE:0000000000000078 ...
E: 420985 [EM]Failed to Send CHIP MessageCounter:101059289 on exchange 20090i sendCount: 4 max retries: 4
I: 421009 [DIS]Checking node lookup status after 200 ms
E: 422089 [EM]Failed to Send CHIP MessageCounter:101059290 on exchange 20091i sendCount: 4 max retries: 4
D: 424040 [IN]SecureSession[0x200037e0]: MarkAsDefunct Type:2 LSID:48652
I: 424046 [DMG]Time out! failed to receive invoke command response from Exchange: 20090i
E: Binding command was not applied! Reason: 32
D: 425184 [IN]SecureSession[0x200037e0]: MarkAsDefunct Type:2 LSID:48652
I: 425190 [DMG]Time out! failed to receive invoke command response from Exchange: 20091i
E: Binding command was not applied! Reason: 32
I: 425202 [DL]OpenThread SED interval is 1000ms
I: Button has been pressed, keep in this state for at least 500 ms to change light sensitivity of binded lighting devices.
I: Notify Bounded Cluster | endpoint: 1 cluster: 6
I: 465809 [DIS]Checking node lookup status after 45000 ms
E: 465814 [DIS]OperationalSessionSetup[1:0000000000000078]: operational discovery failed: 32
E: 465822 [SVR]Failed to establish connection to node 0x0000000000000078
E: 465829 [SVR]Failed to establish connection to node 0x0000000000000078

 

Fullscreen light bulb logs.txt Download

Terminal ready
I: 82807 [EM]>>> [E:20082r S:49019 M:101059274] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 82819 [DMG]AccessControl: denied
I: 82824 [EM]<<< [E:20082r S:49019 M:138837793 (Ack:101059274)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 82837 [IN](S) Sending msg 138837793 on secure session with LSID: 49019
I: 83083 [EM]>>> [E:20082r S:49019 M:101059275 (Ack:138837793)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 105122 [EM]>>> [E:39165r S:0 M:22467518] (U) Msg RX from 0:05750D0F3DF6FC3E [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 105134 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004ce0
I: 105141 [IN]CASE Server disabling CASE session setups
I: 105147 [EM]<<< [E:39165r S:0 M:20916448 (Ack:22467518)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 105159 [IN](U) Sending msg 20916448 to IP address 'UDP:[fd0a:abb0:77a8:c46b:754f:2b4a:7bdf:f959]:39594'
I: 105170 [SC]Received Sigma1 msg
I: 105178 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000078
I: 105390 [EM]<<< [E:39165r S:0 M:20916449 (Ack:22467518)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 105403 [IN](U) Sending msg 20916449 to IP address 'UDP:[fd0a:abb0:77a8:c46b:754f:2b4a:7bdf:f959]:39594'
I: 105414 [SC]Sent Sigma2 msg
I: 105587 [EM]>>> [E:39165r S:0 M:22467519 (Ack:20916449)] (U) Msg RX from 0:05750D0F3DF6FC3E [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 105600 [EM]<<< [E:39165r S:0 M:20916450 (Ack:22467519)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 105613 [IN](U) Sending msg 20916450 to IP address 'UDP:[fd0a:abb0:77a8:c46b:754f:2b4a:7bdf:f959]:39594'
I: 105623 [SC]Received Sigma3 msg
E: 105632 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 105831 [DL]Long dispatch time: 189 ms, for event type 2
I: 105931 [EM]<<< [E:39165r S:0 M:20916451 (Ack:22467519)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 105944 [IN](U) Sending msg 20916451 to IP address 'UDP:[fd0a:abb0:77a8:c46b:754f:2b4a:7bdf:f959]:39594'
I: 105956 [SC]SecureSession[0x20003320]: Moving from state 'kEstablishing' --> 'kActive'
D: 105964 [IN]SecureSession[0x20003320]: Activated - Type:2 LSID:49020
D: 105971 [IN]New secure session activated for device <000000000001B669, 1>, LSID:49020 PSID:38157!
I: 105980 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 105986 [IN]CASE Server enabling CASE session setups
D: 105991 [IN]SecureSession[0x20003548]: Allocated Type:2 LSID:49021
E: 105997 [DL]Long dispatch time: 161 ms, for event type 2
I: 106015 [EM]>>> [E:39166r S:49020 M:215868018] (S) Msg RX from 1:000000000001B669 [D7CE] --- Type 0001:06 (IM:WriteRequest)
D: 106028 [IM]Received Write request
I: 106160 [EM]<<< [E:39166r S:49020 M:153229492 (Ack:215868018)] (S) Msg TX to 1:000000000001B669 [D7CE] --- Type 0001:07 (IM:WriteResponse)
I: 106173 [IN](S) Sending msg 153229492 on secure session with LSID: 49020
I: 106181 [EM]>>> [E:39165r S:0 M:22467520 (Ack:20916451)] (U) Msg RX from 0:05750D0F3DF6FC3E [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 106227 [EM]>>> [E:39166r S:49020 M:215868019 (Ack:153229492)] (S) Msg RX from 1:000000000001B669 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 113587 [EM]>>> [E:20083r S:49019 M:101059276] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 113600 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 113604 [ZCL]On Command - OffWaitTime :  0
I: 113608 [ZCL]On/Toggle Command - Stop Timer
I: 113628 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 113640 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 113657 [EM]<<< [E:20083r S:49019 M:138837794 (Ack:101059276)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 113670 [IN](S) Sending msg 138837794 on secure session with LSID: 49019
I: 113678 [ZCL]Event: move from 1
I: 113681 [ZCL] to 254 
I: 113683 [ZCL](diff +1)
I: 113686 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 113863 [EM]>>> [E:20083r S:49019 M:101059277 (Ack:138837794)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 116368 [EM]>>> [E:20084r S:49019 M:101059278] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 116380 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 116386 [EM]<<< [E:20084r S:49019 M:138837795 (Ack:101059278)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 116399 [IN](S) Sending msg 138837795 on secure session with LSID: 49019
I: 116407 [ZCL]Event: move from 254
I: 116411 [ZCL] to 1 
I: 116413 [ZCL](diff -1)
I: 116415 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 116431 [ZCL]Setting on/off to OFF due to level change
I: 116436 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 116459 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 116470 [ZCL]Off completed. reset OnTime to  0
I: 116475 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 116639 [EM]>>> [E:20084r S:49019 M:101059279 (Ack:138837795)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 118688 [EM]>>> [E:20085r S:49019 M:101059280] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 118701 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 118705 [ZCL]On Command - OffWaitTime :  0
I: 118709 [ZCL]On/Toggle Command - Stop Timer
I: 118732 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 118744 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 118751 [EM]<<< [E:20085r S:49019 M:138837796 (Ack:101059280)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 118764 [IN](S) Sending msg 138837796 on secure session with LSID: 49019
I: 118772 [ZCL]Event: move from 1
I: 118776 [ZCL] to 254 
I: 118778 [ZCL](diff +1)
I: 118781 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 119041 [EM]>>> [E:20085r S:49019 M:101059281 (Ack:138837796)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 120841 [EM]>>> [E:20086r S:49019 M:101059282] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 120853 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 120859 [EM]<<< [E:20086r S:49019 M:138837797 (Ack:101059282)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 120872 [IN](S) Sending msg 138837797 on secure session with LSID: 49019
I: 120880 [ZCL]Event: move from 254
I: 120884 [ZCL] to 1 
I: 120886 [ZCL](diff -1)
I: 120888 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 120904 [ZCL]Setting on/off to OFF due to level change
I: 120909 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 120928 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 120940 [ZCL]Off completed. reset OnTime to  0
I: 120945 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 121114 [EM]>>> [E:20086r S:49019 M:101059283 (Ack:138837797)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 153991 [DL]OpenThread State Changed (Flags: 0x00000400)
I: 184878 [EM]>>> [E:20087r S:49019 M:101059284] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 184891 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 184896 [ZCL]On Command - OffWaitTime :  0
I: 184900 [ZCL]On/Toggle Command - Stop Timer
I: 184922 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 184934 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 184941 [EM]<<< [E:20087r S:49019 M:138837798 (Ack:101059284)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 184954 [IN](S) Sending msg 138837798 on secure session with LSID: 49019
I: 184962 [ZCL]Event: move from 1
I: 184965 [ZCL] to 254 
I: 184967 [ZCL](diff +1)
I: 184969 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 185150 [EM]>>> [E:20087r S:49019 M:101059285 (Ack:138837798)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 225361 [EM]>>> [E:20088r S:49019 M:101059286] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 225373 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 225379 [EM]<<< [E:20088r S:49019 M:138837799 (Ack:101059286)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 225392 [IN](S) Sending msg 138837799 on secure session with LSID: 49019
I: 225400 [ZCL]Event: move from 254
I: 225403 [ZCL] to 1 
I: 225405 [ZCL](diff -1)
I: 225407 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 225423 [ZCL]Setting on/off to OFF due to level change
I: 225428 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 225448 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 225460 [ZCL]Off completed. reset OnTime to  0
I: 225464 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 225638 [EM]>>> [E:20088r S:49019 M:101059287 (Ack:138837799)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 286309 [DL]SRP Client was stopped, because current server is no longer detected.
D: 286317 [DL]OpenThread State Changed (Flags: 0x10000285)
D: 286322 [DL]   Device Role: LEADER
D: 286326 [DL]   Partition Id: 0x199DE521
D: 286330 [DL]   Thread Unicast Addresses:
D: 286334 [DL]        fd2d:b5c7:7093:108c:0:ff:fe00:fc00/64 valid
D: 286340 [DL]        fd2d:b5c7:7093:108c:0:ff:fe00:f000/64 valid rloc
D: 286346 [DL]        fd2d:b5c7:7093:108c:3593:54dd:2151:919e/64 valid
D: 286352 [DL]        fe80::4c6c:42f2:7759:638d/64 valid preferred
D: 286360 [DL]OpenThread State Changed (Flags: 0x00000002)
D: 286366 [DL]   Thread Unicast Addresses:
D: 286369 [DL]        fd2d:b5c7:7093:108c:0:ff:fe00:fc00/64 valid
D: 286375 [DL]        fd2d:b5c7:7093:108c:0:ff:fe00:f000/64 valid rloc
D: 286382 [DL]        fd2d:b5c7:7093:108c:3593:54dd:2151:919e/64 valid
D: 286388 [DL]        fe80::4c6c:42f2:7759:638d/64 valid preferred

 

Fullscreen light bulb logs after adding back the otbr.txt Download

762466 [DL]OpenThread State Changed (Flags: 0x00000200)
I: 770572 [DL]SRP Client was started, detected server: fd2d:b5c7:7093:108c:36f4:d6ee:d900:3393
D: 770581 [DL]OpenThread State Changed (Flags: 0x00000200)
D: 771924 [DL]SRP update succeeded
I: 782664 [EM]>>> [E:20092r S:0 M:155953181] (U) Msg RX from 0:AFF22849ABBA2F2D [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 782675 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004ce0
I: 782683 [IN]CASE Server disabling CASE session setups
I: 782688 [EM]<<< [E:20092r S:0 M:20916452 (Ack:155953181)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 782701 [IN](U) Sending msg 20916452 to IP address 'UDP:[fdf5:ef51:78cf:1:e539:3d21:814b:142f]:5540'
I: 782711 [SC]Received Sigma1 msg
I: 782718 [EM]<<< [E:20092r S:0 M:20916453 (Ack:155953181)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
I: 782731 [IN](U) Sending msg 20916453 to IP address 'UDP:[fdf5:ef51:78cf:1:e539:3d21:814b:142f]:5540'
I: 782917 [EM]>>> [E:20092r S:0 M:155953182 (Ack:20916453)] (U) Msg RX from 0:AFF22849ABBA2F2D [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 782963 [EM]>>> [E:20092r S:0 M:155953183 (Ack:20916453)] (U) Msg RX from 0:AFF22849ABBA2F2D [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 782976 [SC]Success status report received. Session was established
I: 783075 [SC]SecureSession[0x20003548]: Moving from state 'kEstablishing' --> 'kActive'
D: 783083 [IN]SecureSession[0x20003548]: Activated - Type:2 LSID:49021
D: 783089 [IN]New secure session activated for device <0000000000000073, 1>, LSID:49021 PSID:48654!
I: 783098 [IN]CASE Session established to peer: <0000000000000073, 1>
I: 783104 [IN]CASE Server enabling CASE session setups
D: 783109 [IN]SecureSession[0x20003600]: Allocated Type:2 LSID:49022
I: 783115 [EM]<<< [E:20092r S:0 M:20916454 (Ack:155953183)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 783128 [IN](U) Sending msg 20916454 to IP address 'UDP:[fdf5:ef51:78cf:1:e539:3d21:814b:142f]:5540'
I: 783139 [EM]>>> [E:20093r S:49021 M:110905607] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 783151 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 783156 [ZCL]On Command - OffWaitTime :  0
I: 783160 [ZCL]On/Toggle Command - Stop Timer
I: 783184 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 783195 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 783203 [EM]<<< [E:20093r S:49021 M:198310326 (Ack:110905607)] (S) Msg TX to 1:0000000000000073 [D7CE] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 783216 [IN](S) Sending msg 198310326 on secure session with LSID: 49021
I: 783223 [ZCL]Event: move from 1
I: 783226 [ZCL] to 254 
I: 783229 [ZCL](diff +1)
I: 783231 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 783352 [EM]>>> [E:20093r S:49021 M:110905608 (Ack:198310326)] (S) Msg RX from 1:0000000000000073 [D7CE] --- Type 0000:10 (SecureChannel:StandaloneAck

[jayveer]

Hi Charlie  , any update ?