[BUG] Device can't resume a persisted subscription when the device restarts(like power down) unexpectedly #28825
Assignees
Labels
Comments
|
@lpbeliveau-silabs Hi Louis-Philip, I followed what GuoTao commented, and I think when ReportScheduler was added it broke subscription resumption. The analysis is correct that the ReadHandlerNode is currently only created on SubscriptionEstablished, but with current code subscription resumption needs the node to be there at OnBecameReportable time. Could you look into this, or help me get familiar with ReportScheduler to make the right change here? |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Reproduction steps
enable the flag 'chip_persist_subscriptions=true' in your project,and compile it.
the device's log
█▀▀▀▀▀█ ▀▀ ▄█▄▄▀▀ █ █▀▀▀▀▀█
█ ███ █ ▄█▀██ █▀█▄ ▀ █ ███ █
█ ▀▀▀ █ ▄▄ ▄▀▀█ ▄ ▀ █ ▀▀▀ █
▀▀▀▀▀▀▀ ▀▄▀▄▀▄▀▄█▄█▄▀ ▀▀▀▀▀▀▀
▄▄▀▄█▀▀ ▀ ▀ █▀▀ ▄█▄ ▀ ▄ █ █
▄▀ ▀▀ ▀ ▀▀ ▄██▀▀ ▄▄ ▄▀█▀▄▀ ▄
▀█▀ █▄▀▀▄█▄ ▀▀▀▄██▄█ ▀ █ █▀▄
▀▀▀ ███▀▀▄▄▀█ ▄▄▀█▄▄▄█▄█▄
▀ █ ▀▀▀▀██ ▄▄█▄▄█▄▄██ █▄▀ █
▀▄▄█▀ ▀ █ ▄▄ █▀▀█▄█ ▄▄▀ █
▀ ▀ ▀▀ █ ▄ █▄▄ █ ██▀▀▀█ ▀▄▄
█▀▀▀▀▀█ ▄ ▄█▄ ▄▀ ███ ▀ █▄█ ▀
█ ███ █ ▀█ ▄ ▀▀ ▄ ▀▀▀▀▀▄ ▄▀
█ ▀▀▀ █ ▀███▄▀▀▀▄█▄ ▄▀▀▄▄▀▄█
▀▀▀▀▀▀▀ ▀ ▀ ▀ ▀▀ ▀▀▀ ▀ ▀
[452[P][DL]OpenThread SED interval is 250ms
[453[D][IN]SecureSession[0x400ea88]: Allocated Type:1 LSID:19076
[455[D][SC]Assigned local session key ID 19076
[455[D][SC]Waiting for PBKDF param request
[456[P][DIS]Updating services using commissioning mode 1
[457[D][DL]Using Thread extended MAC for hostname.
[458[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=1
[462[P][DL]Started Advertising at 60 ms
[466[D][ZCL]GeneralDiagnostics: OnHardwareFaultsDetect
[467[D][DMG]Endpoint 0, Cluster 0x0000_0033 update version to aaf8c93c
[468[D][EVL]LogEvent event number: 0x0000000000000002 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x0 Sys timestamp: 0x000000000000018A
[512[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to ea4095d3
[514[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to ea4095d4
[11002[P][DL]BLE is connected with device: 0.
[11232[P][DL]BLE MTU size has been changed to 247.
[12450[P][BLE]local and remote recv window sizes = 6
[12451[P][BLE]selected BTP version 4
[12452[P][BLE]using BTP fragment sizes rx 244 / tx 244.
[12695[D][IN]BLE EndPoint 0x4009640 Connection Complete
[12696[P][EM]>>> [E:55587r S:0 M:142561936] (U) Msg RX from 0:28F6BFB4939D196B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[12699[D][EM]Handling via exchange: 55587r, Delegate: 0x4010530
[12700[D][SC]Received PBKDF param request
[12701[D][SC]Peer assigned session ID 15334
[12702[D][SC]Including MRP parameters in PBKDF param response
[12704[P][EM]<<< [E:55587r S:0 M:21480342] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[12706[P]IN Sending msg 21480342 to IP address 'BLE'
[12707[D][SC]Sent PBKDF param response
[12708[P][SVR]Commissioning session establishment step started
[12842[D][map]chip over ble connection established
[12843[P][gb]Generic Behavior, Device state move to BLE ESTABLISHED ,last state is START ADV
[12844[P][gb]Will perform the BLE ESTABLISHED event
[12845[P][EM]>>> [E:55587r S:0 M:142561937] (U) Msg RX from 0:28F6BFB4939D196B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[12847[D][EM]Found matching exchange: 55587r, Delegate: 0x4010530
[12848[D][SC]Received spake2p msg1
[13017[P][EM]<<< [E:55587r S:0 M:21480343] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[13019[P]IN Sending msg 21480343 to IP address 'BLE'
[13020[D][SC]Sent spake2p msg2
[13085[P][EM]>>> [E:55587r S:0 M:142561938] (U) Msg RX from 0:28F6BFB4939D196B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[13087[D][EM]Found matching exchange: 55587r, Delegate: 0x4010530
[13089[D][SC]Received spake2p msg3
[13090[D][SC]Sending status report. Protocol code 0, exchange 55587
[13091[P][EM]<<< [E:55587r S:0 M:21480344] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[13093[P]IN Sending msg 21480344 to IP address 'BLE'
[13095[P][SC]SecureSession[0x400ea88, LSID:19076]: State change 'kEstablishing' --> 'kActive'
[13096[D][IN]SecureSession[0x400ea88]: Activated - Type:1 LSID:19076
[13098[D][IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:19076 PSID:15334!
[13099[P][SVR]Commissioning completed session establishment step
[13100[P][DIS]Updating services using commissioning mode 0
[13101[D][DL]Using Thread extended MAC for hostname.
[13102[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=0
[13104[D][DIS]Scheduling extended discovery timeout in 86400s
[13105[P][SVR]Device completed Rendezvous process
[13233[P][EM]>>> [E:55588r S:19076 M:137332488] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[13235[D][EM]Handling via exchange: 55588r, Delegate: 0x40081e4
[13236[D][IM]Received Read request
[13243[D][DMG]IM RH moving to [CanStartReporting]
[13244[D][DMG]Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
[13246[D][DMG]RE:Run Cluster 31, Attribute 3 is dirty
[13247[D][DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[13249[D][DMG]RE:Run Cluster 28, Attribute 4 is dirty
[13249[D][DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[13251[D][DMG]RE:Run Cluster 28, Attribute 2 is dirty
[13252[D][DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[13254[D][DMG]RE:Run Cluster 30, Attribute 3 is dirty
[13255[D][DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[13257[D][DMG]RE:Run Cluster 30, Attribute 2 is dirty
[13257[D][DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[13259[D][DMG]RE:Run Cluster 30, Attribute 1 is dirty
[13260[D][DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[13262[D][DMG]RE:Run Cluster 30, Attribute 0 is dirty
[13263[D][DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[13265[D][DMG]RE:Run Cluster 31, Attribute fffc is dirty
[13266[D][DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[13267[D][DMG] Sending report (payload has 228 bytes)...
[13270[P][EM]<<< [E:55588r S:19076 M:180121678] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[13272[P]IN Sending msg 180121678 on secure session with LSID: 19076
[13376[D][DMG] OnReportConfirm: NumReports = 0
[13377[D][DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
[13378[D][DMG]IM RH moving to [AwaitingDestruction]
[13384[P][DL]KVS, Matter key [g/su/0] not found in persistent storage.
[13390[P][DL]KVS, Matter key [g/su/1] not found in persistent storage.
[13397[P][DL]KVS, Matter key [g/su/2] not found in persistent storage.
[13403[P][DL]KVS, Matter key [g/su/3] not found in persistent storage.
[13409[P][DL]KVS, Matter key [g/su/4] not found in persistent storage.
[13415[P][DL]KVS, Matter key [g/su/5] not found in persistent storage.
[13416[D][DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[13476[P][EM]>>> [E:55589r S:19076 M:137332489] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[13478[D][EM]Handling via exchange: 55589r, Delegate: 0x40081e4
[13480[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[13482[P][FS]GeneralCommissioning: Received ArmFailSafe (60s)
[13483[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a76
[13484[D][DMG]Command handler moving to [ Preparing]
[13485[D][DMG]Command handler moving to [AddingComm]
[13486[D][DMG]Command handler moving to [AddedComma]
[13487[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[13489[P][EM]<<< [E:55589r S:19076 M:180121679] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[13491[P]IN Sending msg 180121679 on secure session with LSID: 19076
[13492[D][DMG]Command handler moving to [CommandSen]
[13493[D][DMG]Command handler moving to [AwaitingDe]
[13622[P][EM]>>> [E:55590r S:19076 M:137332490] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[13624[D][EM]Handling via exchange: 55590r, Delegate: 0x40081e4
[13626[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
[13628[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a77
[13629[D][DMG]Command handler moving to [ Preparing]
[13630[D][DMG]Command handler moving to [AddingComm]
[13631[D][DMG]Command handler moving to [AddedComma]
[13632[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[13634[P][EM]<<< [E:55590r S:19076 M:180121680] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[13636[P]IN Sending msg 180121680 on secure session with LSID: 19076
[13637[D][DMG]Command handler moving to [CommandSen]
[13638[D][DMG]Command handler moving to [AwaitingDe]
[13817[P][EM]>>> [E:55591r S:19076 M:137332491] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[13819[D][EM]Handling via exchange: 55591r, Delegate: 0x40081e4
[13821[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[13823[P][ZCL]OpCreds: Certificate Chain request received for PAI
[13824[D][DMG]Command handler moving to [ Preparing]
[13825[D][DMG]Command handler moving to [AddingComm]
[13826[D][DMG]Command handler moving to [AddedComma]
[13827[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[13831[P][EM]<<< [E:55591r S:19076 M:180121681] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[13833[P]IN Sending msg 180121681 on secure session with LSID: 19076
[14010[D][DMG]Command handler moving to [CommandSen]
[14011[D][DMG]Command handler moving to [AwaitingDe]
[14207[P][EM]>>> [E:55592r S:19076 M:137332492] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[14209[D][EM]Handling via exchange: 55592r, Delegate: 0x40081e4
[14211[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[14213[P][ZCL]OpCreds: Certificate Chain request received for DAC
[14214[D][DMG]Command handler moving to [ Preparing]
[14215[D][DMG]Command handler moving to [AddingComm]
[14216[D][DMG]Command handler moving to [AddedComma]
[14217[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[14221[P][EM]<<< [E:55592r S:19076 M:180121682] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[14223[P]IN Sending msg 180121682 on secure session with LSID: 19076
[14224[D][DMG]Command handler moving to [CommandSen]
[14225[D][DMG]Command handler moving to [AwaitingDe]
[14597[P][EM]>>> [E:55593r S:19076 M:137332493] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[14600[D][EM]Handling via exchange: 55593r, Delegate: 0x40081e4
[14601[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
[14603[P][ZCL]OpCreds: Received an AttestationRequest command
[14619[P][ZCL]OpCreds: AttestationRequest successful.
[14619[D][DMG]Command handler moving to [ Preparing]
[14620[D][DMG]Command handler moving to [AddingComm]
[14621[D][DMG]Command handler moving to [AddedComma]
[14623[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[14628[P][EM]<<< [E:55593r S:19076 M:180121683] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[14630[P]IN Sending msg 180121683 on secure session with LSID: 19076
[14741[D][DMG]Command handler moving to [CommandSen]
[14742[D][DMG]Command handler moving to [AwaitingDe]
[14987[P][EM]>>> [E:55594r S:19076 M:137332494] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[14989[D][EM]Handling via exchange: 55594r, Delegate: 0x40081e4
[14991[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
[14992[P][ZCL]OpCreds: Received a CSRRequest command
[14993[D][ZCL]OpCreds: Finding fabric with fabricIndex 0x0
[15018[P][ZCL]OpCreds: AllocatePendingOperationalKey succeeded
[15034[P][ZCL]OpCreds: CSRRequest successful.
[15035[D][DMG]Command handler moving to [ Preparing]
[15036[D][DMG]Command handler moving to [AddingComm]
[15037[D][DMG]Command handler moving to [AddedComma]
[15038[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[15042[P][EM]<<< [E:55594r S:19076 M:180121684] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[15044[P]IN Sending msg 180121684 on secure session with LSID: 19076
[15131[D][DMG]Command handler moving to [CommandSen]
[15132[D][DMG]Command handler moving to [AwaitingDe]
[15329[P][EM]>>> [E:55595r S:19076 M:137332495] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[15331[D][EM]Handling via exchange: 55595r, Delegate: 0x40081e4
[15333[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
[15334[P][ZCL]OpCreds: Received an AddTrustedRootCertificate command
[15386[P][DL]KVS, Matter key [f/1/r] not found in persistent storage.
[15387[P][ZCL]OpCreds: AddTrustedRootCertificate successful.
[15388[D][DMG]Command handler moving to [ Preparing]
[15389[D][DMG]Command handler moving to [AddingComm]
[15390[D][DMG]Command handler moving to [AddedComma]
[15391[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[15393[P][EM]<<< [E:55595r S:19076 M:180121685] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[15395[P]IN Sending msg 180121685 on secure session with LSID: 19076
[15475[D][DMG]Command handler moving to [CommandSen]
[15476[D][DMG]Command handler moving to [AwaitingDe]
[15671[P][EM]>>> [E:55596r S:19076 M:137332496] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[15674[D][EM]Handling via exchange: 55596r, Delegate: 0x40081e4
[15676[D][DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
[15677[P][ZCL]OpCreds: Received an AddNOC command
[15683[P][DL]KVS, Matter key [f/1/o] not found in persistent storage.
[15691[P][DL]KVS, Matter key [f/1/n] not found in persistent storage.
[15697[P][DL]KVS, Matter key [f/1/i] not found in persistent storage.
[15698[P][FP]Validating NOC chain
[15792[P][FP]NOC chain validation successful
[15793[P][FP]Added new fabric at index: 0x1
[15794[P][FP]Assigned compressed fabric ID: 0xA612970B973EFE15, node ID: 0x0000000000000001
[15795[P][TS]Last Known Good Time: 2023-08-23T12:10:48
[15796[P][TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
[15797[P][TS]Retaining current Last Known Good Time
[15798[D][map]OnFabricUpdated -> fabric index 1
[15799[D][DMG]Endpoint 0, Cluster 0x0000_003E update version to 66251a9
[15800[D][DMG]Endpoint 0, Cluster 0x0000_003E update version to 66251aa
[15806[P][DL]KVS, Matter key [g/sri] not found in persistent storage.
[15813[P][DL]KVS, Matter key [f/1/g] not found in persistent storage.
[15821[P][DL]KVS, save in flash the value of the Matter key [f/1/k/0] with PDM id: 1285
[15823[P][DL]KVS, save in flash the Matter key [f/1/k/0] with PDM id: 1029 and length 8
[15829[P][DL]KVS, Matter key [g/gfl] not found in persistent storage.
[15835[P][DL]KVS, save in flash the value of the Matter key [g/gfl] with PDM id: 1286
[15837[P][DL]KVS, save in flash the Matter key [g/gfl] with PDM id: 1030 and length 6
[15843[P][DL]KVS, save in flash the value of the Matter key [f/1/g] with PDM id: 1287
[15845[P][DL]KVS, save in flash the Matter key [f/1/g] with PDM id: 1031 and length 6
[15852[P][DL]KVS, save in flash the value of the Matter key [f/1/ac/0/0] with PDM id: 1288
[15853[P][DL]KVS, save in flash the Matter key [f/1/ac/0/0] with PDM id: 1032 and length 11
[15855[D][EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000003DA4
[15857[P][ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
[15859[D][DL]Using Thread extended MAC for hostname.
[15860[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[15861[D][DMG]Endpoint 0, Cluster 0x0000_003E update version to 66251ab
[15863[D][DMG]Endpoint 0, Cluster 0x0000_003E update version to 66251ac
[15864[D][DMG]Command handler moving to [ Preparing]
[15865[D][DMG]Command handler moving to [AddingComm]
[15866[D][DMG]Command handler moving to [AddedComma]
[15867[P][ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
[15868[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[15870[P][EM]<<< [E:55596r S:19076 M:180121686] (S) Msg TX to 1:FFFFFFFB00000000 [FE15] --- Type 0001:09 (IM:InvokeCommandResponse)
[15872[P]IN Sending msg 180121686 on secure session with LSID: 19076
[15962[D][DMG]Command handler moving to [CommandSen]
[15963[D][DMG]Command handler moving to [AwaitingDe]
[15965[P][EM]>>> [E:55597r S:19076 M:137332497] (S) Msg RX from 1:FFFFFFFB00000000 [FE15] --- Type 0001:08 (IM:InvokeCommandRequest)
[15968[D][EM]Handling via exchange: 55597r, Delegate: 0x40081e4
[15969[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
[15976[P][DL]KVS, save in flash the value of the Matter key [g/fs/n] with PDM id: 1289
[15978[P][DL]KVS, save in flash the Matter key [g/fs/n] with PDM id: 1033 and length 7
[15979[D][DMG]Command handler moving to [ Preparing]
[15980[D][DMG]Command handler moving to [AddingComm]
[15981[D][DMG]Command handler moving to [AddedComma]
[15982[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a78
[15984[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[15985[P][EM]<<< [E:55597r S:19076 M:180121687] (S) Msg TX to 1:FFFFFFFB00000000 [FE15] --- Type 0001:09 (IM:InvokeCommandResponse)
[15987[P]IN Sending msg 180121687 on secure session with LSID: 19076
[15989[D][DMG]Command handler moving to [CommandSen]
[15990[D][DMG]Command handler moving to [AwaitingDe]
[16108[P][EM]>>> [E:55598r S:19076 M:137332498] (S) Msg RX from 1:FFFFFFFB00000000 [FE15] --- Type 0001:08 (IM:InvokeCommandRequest)
[16110[D][EM]Handling via exchange: 55598r, Delegate: 0x40081e4
[16112[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[16114[P][FS]GeneralCommissioning: Received ArmFailSafe (143s)
[16115[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a79
[16116[D][DMG]Command handler moving to [ Preparing]
[16117[D][DMG]Command handler moving to [AddingComm]
[16118[D][DMG]Command handler moving to [AddedComma]
[16119[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[16121[P][EM]<<< [E:55598r S:19076 M:180121688] (S) Msg TX to 1:FFFFFFFB00000000 [FE15] --- Type 0001:09 (IM:InvokeCommandResponse)
[16123[P]IN Sending msg 180121688 on secure session with LSID: 19076
[16124[D][DMG]Command handler moving to [CommandSen]
[16125[D][DMG]Command handler moving to [AwaitingDe]
[16255[P][EM]>>> [E:55599r S:19076 M:137332499] (S) Msg RX from 1:FFFFFFFB00000000 [FE15] --- Type 0001:08 (IM:InvokeCommandRequest)
[16257[D][EM]Handling via exchange: 55599r, Delegate: 0x40081e4
[16259[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
[16261[P][DL]KVS, save in flash the value of the Matter key [g/fs/n] with PDM id: 1289
[16265[D][DMG]Decreasing reference count for CommandHandler, remaining 1
[16266[D][map]service is provisioned
[16267[D][DL]OpenThread State Changed (Flags: 0x1117d11d)
[16268[D][DL] Device Role: DETACHED
[16269[D][DL] Network Name: OpenThreadDemo
[16270[D][DL] PAN Id: 0x6666
[16271[D][DL] Extended PAN Id: 0x1111116666223344
[16271[D][DL] Channel: 16
[16272[D][DL] Mesh Prefix: fd29:119e:23dc:90e8:0:0:0:0/64
[16273[D][DL] Thread Unicast Addresses:
[16274[D][DL] fd29:119e:23dc:90e8:c57e:3ecb:cc49:16a7/64 valid
[16276[D][DL] fe80:0:0:0:8830:e1eb:4252:bef4/64 valid preferred
[17453[P][DL]SRP Client was started, detected server: fd29:119e:23dc:90e8:2570:188b:16e3:8234
[17455[D][DL]OpenThread State Changed (Flags: 0x200002a4)
[17456[D][DL] Device Role: CHILD
[17457[D][DL] Partition Id: 0x34C3B39C
[17458[D][DL]Thread Attached updating Multicast address
[17459[P][SVR]Joining Multicast groups
[17460[P][DL]KVS, get the value of Matter key [f/1/g] with PDM id: 1287
[17461[D][DL]OpenThread State Changed (Flags: 0x00000001)
[17462[D][DL] Thread Unicast Addresses:
[17463[D][DL] fde5:4e59:fb89:1:5652:5490:efa4:8f40/64 valid preferred
[17465[D][DL] fd29:119e:23dc:90e8:0:ff:fe00:182f/64 valid rloc
[17466[D][DL] fd29:119e:23dc:90e8:c57e:3ecb:cc49:16a7/64 valid
[17467[D][DL] fe80:0:0:0:8830:e1eb:4252:bef4/64 valid preferred
[17469[D][DMG]Command handler moving to [ Preparing]
[17471[D][DMG]Command handler moving to [AddingComm]
[17472[D][DMG]Command handler moving to [AddedComma]
[17472[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a7a
[17474[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[17475[P][EM]<<< [E:55599r S:19076 M:180121689] (S) Msg TX to 1:FFFFFFFB00000000 [FE15] --- Type 0001:09 (IM:InvokeCommandResponse)
[17478[P]IN Sending msg 180121689 on secure session with LSID: 19076
[17569[D][DMG]Command handler moving to [CommandSen]
[17570[D][DMG]Command handler moving to [AwaitingDe]
[17571[D][DL]Using Thread extended MAC for hostname.
[17571[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[17573[P][SVR]Operational advertising enabled
[18330[D][DL]SRP update succeeded
[18330[P][DIS]Setting operational delegate post init
[18331[P][SVR]Server initialization complete
[18332[P][DIS]Updating services using commissioning mode 0
[18333[D][DL]Using Thread extended MAC for hostname.
[18334[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[18336[P][DL]advertising srp service: A612970B973EFE15-0000000000000001._matter._tcp
[18337[D][DL]Using Thread extended MAC for hostname.
[18338[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=0
[18341[P][DL]advertising srp service: 2571BFC5BE3FF280._matterc._udp
[18348[P][DL]KVS, Matter key [g/su/0] not found in persistent storage.
[18355[P][DL]KVS, Matter key [g/su/1] not found in persistent storage.
[18362[P][DL]KVS, Matter key [g/su/2] not found in persistent storage.
[18369[P][DL]KVS, Matter key [g/su/3] not found in persistent storage.
[18376[P][DL]KVS, Matter key [g/su/4] not found in persistent storage.
[18382[P][DL]KVS, Matter key [g/su/5] not found in persistent storage.
[18383[P][IM]No subscriptions to resume
[19701[D][DL]SRP update succeeded
[20092[D][IN]UDP Message Received packet nb : 1 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[49164] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 166
[20095[P][EM]>>> [E:55600r S:0 M:142561939] (U) Msg RX from 0:01319A7352431340 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[20097[D][EM]Handling via exchange: 55600r, Delegate: 0x400f000
[20098[P][IN]CASE Server received Sigma1 message . Starting handshake. EC 0x400fea8
[20100[P][EM]<<< [E:55600r S:0 M:21480345 (Ack:142561939)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[20102[P]IN Sending msg 21480345 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542]:49164'
[20105[D][EM]Flushed pending ack for MessageCounter:142561939 on exchange 55600r
[20107[P][SC]Received Sigma1 msg
[20108[D][SC]Peer assigned session key ID 15335
[20109[P][DL]KVS, get the value of Matter key [f/1/g] with PDM id: 1287
[20111[P][DL]KVS, get the value of Matter key [f/1/k/0] with PDM id: 1285
[20115[P][SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
[20182[D][SC]Including MRP parameters
[20185[P][EM]<<< [E:55600r S:0 M:21480346 (Ack:142561939)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[20188[P]IN Sending msg 2148034 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542]:49164'
[20191[P][SC]Sent Sigma2 msg
[20695[D][IN]UDP Message Received packet nb : 2 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[49164] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 598
[20698[P][EM]>>> [E:55600r S:0 M:142561940 (Ack:21480346)] (U) Msg RX from 0:01319A7352431340 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[20700[D][EM]Found matching exchange: 55600r, Delegate: 0x400f01c
[20702[D][EM]Rxd Ack; Removing MessageCounter:21480346 from Retrans Table on exchange 55600r
[20703[P][EM]<<< [E:55600r S:0 M:21480347 (Ack:142561940)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[20706[P]IN Sending msg 21480347 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:49164'
[20708[D][EM]Flushed pending ack for MessageCounter:142561940 on exchange 55600r
[20709[P][SC]Received Sigma3 msg
[20863[P][DL]KVS, Matter key [g/sri] not found in persistent storage.
[20870[P][DL]KVS, save in flash the value of the Matter key [f/1/s/000000000001B669] with PDM id: 1290
[20871[P][DL]KVS, save in flash the Matter key [f/1/s/000000000001B669] with PDM id: 1034 and length 23
[20879[P][DL]KVS, save in flash the value of the Matter key [g/s/hAdLQ8UmlY3L0JNrUMDNDg==] with PDM id: 1291
[20880[P][DL]KVS, save in flash the Matter key [g/s/hAdLQ8UmlY3L0JNrUMDNDg==] with PDM id: 1035 and length 29
[20888[P][DL]KVS, save in flash the value of the Matter key [g/sri] with PDM id: 1292
[20890[P][DL]KVS, save in flash the Matter key [g/sri] with PDM id: 1036 and length 6
[20891[D][SC]Sending status report. Protocol code 0, exchange 55600
[20892[P][EM]<<< [E:55600r S:0 M:21480348 (Ack:142561940)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[20895[P]IN Sending msg 21480348 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:49164'
[20898[P][SC]SecureSession[0x400e9c8, LSID:19075]: State change 'kEstablishing' --> 'kActive'
[20900[D][IN]SecureSession[0x400e9c8]: Activated - Type:2 LSID:19075
[20902[D][IN]New secure session activated for device <000000000001B669, 1>, LSID:19075 PSID:15335!
[20903[P][IN]CASE Session established to peer: <000000000001B669, 1>
[20905[D][IN]SecureSession[0x400eb48]: Allocated Type:2 LSID:19077
[20906[D][SC]Allocated SecureSession (0x400eb48) - waiting for Sigma1 msg
[20952[D][IN]UDP Message Received packet nb : 3 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[49164] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 59
[20956[P][EM]>>> [E:55601r S:19075 M:90152370] (S) Msg RX from 1:000000000001B669 [FE15] --- Type 0001:08 (IM:InvokeCommandRequest)
[20959[D][EM]Handling via exchange: 55601r, Delegate: 0x40081e4
[20961[D][DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[20962[P][FS]GeneralCommissioning: Received CommissioningComplete
[20970[D][IN]UDP Message Received packet nb : 4 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[49164] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 26
[20977[P][DL]KVS, save in flash the value of the Matter key [g/fs/c] with PDM id: 1293
[20978[P][DL]KVS, save in flash the Matter key [g/fs/c] with PDM id: 1037 and length 7
[20986[P][DL]KVS, save in flash the value of the Matter key [f/1/m] with PDM id: 1294
[20987[P][DL]KVS, save in flash the Matter key [f/1/m] with PDM id: 1038 and length 6
[20989[P][FP]Metadata for Fabric 0x1 persisted to storage.
[20996[P][DL]KVS, save in flash the value of the Matter key [f/1/o] with PDM id: 1295
[20997[P][DL]KVS, save in flash the Matter key [f/1/o] with PDM id: 1039 and length 6
[21005[P][DL]KVS, save in flash the value of the Matter key [f/1/n] with PDM id: 1296
[21006[P][DL]KVS, save in flash the Matter key [f/1/n] with PDM id: 1040 and length 6
[21014[P][DL]KVS, save in flash the value of the Matter key [f/1/i] with PDM id: 1297
[21016[P][DL]KVS, save in flash the Matter key [f/1/i] with PDM id: 1041 and length 6
[21024[P][DL]KVS, save in flash the value of the Matter key [f/1/r] with PDM id: 1298
[21025[P][DL]KVS, save in flash the Matter key [f/1/r] with PDM id: 1042 and length 6
[21027[P][TS]Committing Last Known Good Time to storage: 2023-08-23T12:10:48
[21028[P][DL]KVS, save in flash the value of the Matter key [g/lkgt] with PDM id: 1281
[21037[P][DL]KVS, save in flash the value of the Matter key [g/fidx] with PDM id: 1299
[21038[P][DL]KVS, save in flash the Matter key [g/fidx] with PDM id: 1043 and length 7
[21040[D][map]OnFabricCommitted -> fabric index 1
[21040[P][ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0xA612970B973EFE15, FabricId 0000000000000001, NodeId 0000000000000001, VendorId 0xFFF1
[21043[P][DL]KVS, delete from flash the Matter key [g/fs/c] with PDM id: 1037
[21045[P][DL]KVS, delete from flash the value of the Matter key [g/fs/c] with PDM id: 1293
[21046[P][FS]GeneralCommissioning: Successfully commited pending fabric data
[21048[P][FS]Fail-safe cleanly disarmed
[21048[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to dd9a5a7b
[21050[D][DMG]Command handler moving to [ Preparing]
[21051[D][DMG]Command handler moving to [AddingComm]
[21052[D][DMG]Command handler moving to [AddedComma]
[21053[D][DMG]Decreasing reference count for CommandHandler, remaining 0
[21054[P][EM]<<< [E:55601r S:19075 M:14941064 (Ack:90152370)] (S) Msg TX to 1:000000000001B669 [FE15] --- Type 0001:09 (IM:InvokeCommandResponse)
[21057[P]IN Sending msg 14941064 on secure session with LSID: 19075
[21059[D][DMG]Command handler moving to [CommandSen]
[21062[D][DMG]Command handler moving to [AwaitingDe]
[21063[P][EM]>>> [E:55600r S:0 M:142561941 (Ack:21480348)] (U) Msg RX from 0:01319A7352431340 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[21065[D][EM]Found matching exchange: 55600r, Delegate: 0
[21066[D][EM]Rxd Ack; Removing MessageCounter:21480348 from Retrans Table on exchange 55600r
[21068[P][SVR]Commissioning completed successfully
[21069[P][DIS]Updating services using commissioning mode 0
[21070[D][DL]Using Thread extended MAC for hostname.
[21071[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[21073[D][DL]Using Thread extended MAC for hostname.
[21074[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=0
[21076[D][IN]Expiring all PASE sessions
[21078[D][IN]SecureSession[0x400ea88]: MarkForEviction Type:1 LSID:19076
[21080[P][SC]SecureSession[0x400ea88, LSID:19076]: State change 'kActive' --> 'kPendingEviction'
[21081[D][IN]SecureSession[0x400ea88]: Released - Type:1 LSID:19076
[21082[D][IN]Clearing BLE pending packets.
[21083[P][BLE]Releasing end point's BLE connection back to application.
[21084[P][DL]Closing BLE GATT connection (con 0)
[21085[D][map]commissioning complete
[21086[D][map]nodeId 01b669
[21087[D][map]fabricIndex 1
[21087[P][gb]Generic Behavior, Device state move to COMPLETE ,last state is BLE ESTABLISHED
[21089[P][gb]Will perform the COMMISSION COMPLETE event
[21090[P][gb]Generic Behavior, Device state move to END ,last state is COMPLETE
[21092[D][ZCL]Commissioning complete, notify platform driver to persist network credentials.
[21093[P][DL]KVS, delete from flash the Matter key [g/fs/n] with PDM id: 1033
[21095[P][DL]KVS, delete from flash the value of the Matter key [g/fs/n] with PDM id: 1289
[21127[P][DL]Stopped connectionTimeout timer.
[21128[P][DL]BLE is disconnected with device: 0.
[21469[D][IN]UDP Message Received packet nb : 5 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[49164] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 34
[21472[P][EM]>>> [E:55601r S:19075 M:90152371 (Ack:14941064)] (S) Msg RX from 1:000000000001B669 [FE15] --- Type 0000:10 (SecureChannel:StandaloneAck)
[21475[D][EM]Found matching exchange: 55601r, Delegate: 0
[21476[D][EM]Rxd Ack; Removing MessageCounter:14941064 from Retrans Table on exchange 55601r
[25477[P][DL]OpenThread SED interval is 5000ms
[50349[D][IN]UDP Message Received packet nb : 6 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 166
[50352[P][EM]>>> [E:56103r S:0 M:128469500] (U) Msg RX from 0:DCDD7A98DAB22D9E [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[50354[D][EM]Handling via exchange: 56103r, Delegate: 0x400f000
[50355[P][IN]CASE Server received Sigma1 message . Starting handshake. EC 0x400fea8
[50356[P][EM]<<< [E:56103r S:0 M:21480349 (Ack:128469500)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[50359[P]IN Sending msg 21480349 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[50361[D][EM]Flushed pending ack for MessageCounter:128469500 on exchange 56103r
[50362[P][SC]Received Sigma1 msg
[50363[D][SC]Peer assigned session key ID 51256
[50364[P][DL]KVS, get the value of Matter key [f/1/g] with PDM id: 1287
[50366[P][DL]KVS, get the value of Matter key [f/1/k/0] with PDM id: 1285
[50371[P][SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001
[50373[P][DL]KVS, get the value of Matter key [f/1/i] with PDM id: 1297
[50375[P][DL]KVS, get the value of Matter key [f/1/n] with PDM id: 1296
[50420[P][DL]KVS, get the value of Matter key [f/1/o] with PDM id: 1295
[50439[D][SC]Including MRP parameters
[50442[P][EM]<<< [E:56103r S:0 M:21480350 (Ack:128469500)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[50445[P]IN Sending msg 21480350 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[50448[P][DL]OpenThread SED interval is 250ms
[50448[P][SC]Sent Sigma2 msg
[51026[D][IN]UDP Message Received packet nb : 7 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 598
[51029[P][EM]>>> [E:56103r S:0 M:128469501 (Ack:21480350)] (U) Msg RX from 0:DCDD7A98DAB22D9E [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[51031[D][EM]Found matching exchange: 56103r, Delegate: 0x400f01c
[51032[D][EM]Rxd Ack; Removing MessageCounter:21480350 from Retrans Table on exchange 56103r
[51034[P][EM]<<< [E:56103r S:0 M:21480351 (Ack:128469501)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[51037[P]IN Sending msg 21480351 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[51039[D][EM]Flushed pending ack for MessageCounter:128469501 on exchange 56103r
[51040[P][SC]Received Sigma3 msg
[51049[P][DL]KVS, get the value of Matter key [f/1/r] with PDM id: 1298
[51188[P][DL]KVS, get the value of Matter key [g/sri] with PDM id: 1292
[51190[P][DL]KVS, get the value of Matter key [f/1/s/000000000001B669] with PDM id: 1290
[51192[P][DL]KVS, delete from flash the Matter key [g/s/hAdLQ8UmlY3L0JNrUMDNDg==] with PDM id: 1035
[51193[P][DL]KVS, delete from flash the value of the Matter key [g/s/hAdLQ8UmlY3L0JNrUMDNDg==] with PDM id: 1291
[51196[P][DL]KVS, save in flash the value of the Matter key [f/1/s/000000000001B669] with PDM id: 1290
[51204[P][DL]KVS, save in flash the value of the Matter key [g/s/co6Pf5P2fjnRJZKwYsXWaQ==] with PDM id: 1289
[51206[P][DL]KVS, save in flash the Matter key [g/s/co6Pf5P2fjnRJZKwYsXWaQ==] with PDM id: 1033 and length 29
[51207[D][SC]Sending status report. Protocol code 0, exchange 56103
[51208[P][EM]<<< [E:56103r S:0 M:21480352 (Ack:128469501)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[51211[P]IN Sending msg 21480352 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[51214[P][SC]SecureSession[0x400eb48, LSID:19077]: State change 'kEstablishing' --> 'kActive'
[51216[D][IN]SecureSession[0x400eb48]: Activated - Type:2 LSID:19077
[51217[D][IN]New secure session activated for device <000000000001B669, 1>, LSID:19077 PSID:51256!
[51219[P][IN]CASE Session established to peer: <000000000001B669, 1>
[51220[D][IN]SecureSession[0x400ea88]: Allocated Type:2 LSID:19078
[51222[D][SC]Allocated SecureSession (0x400ea88) - waiting for Sigma1 msg
[51549[D][IN]UDP Message Received packet nb : 8 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 59
[51553[P][EM]>>> [E:56104r S:19077 M:205398527] (S) Msg RX from 1:000000000001B669 [FE15] --- Type 0001:03 (IM:SubscribeRequest)
[51555[D][EM]Handling via exchange: 56104r, Delegate: 0x40081e4
[51556[D][IM]Received Subscribe request
[51562[D][IN]UDP Message Received packet nb : 9 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 26
[51566[P][DMG]Final negotiated min/max parameters: Min = 0s, Max = 1800s
[51568[D][DMG]IM RH moving to [CanStartReporting]
[51575[P][DL]KVS, Matter key [g/su/0] not found in persistent storage.
[51583[P][DL]KVS, Matter key [g/su/1] not found in persistent storage.
[51591[P][DL]KVS, Matter key [g/su/2] not found in persistent storage.
[51599[P][DL]KVS, Matter key [g/su/3] not found in persistent storage.
[51606[P][DL]KVS, Matter key [g/su/4] not found in persistent storage.
[51614[P][DL]KVS, Matter key [g/su/5] not found in persistent storage.
[51622[P][DL]KVS, save in flash the value of the Matter key [g/su/0] with PDM id: 1291
[51623[P][DL]KVS, save in flash the Matter key [g/su/0] with PDM id: 1035 and length 7
[51625[P][EM]>>> [E:56103r S:0 M:128469502 (Ack:21480352)] (U) Msg RX from 0:DCDD7A98DAB22D9E [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[51627[D][EM]Found matching exchange: 56103r, Delegate: 0
[51628[D][EM]Rxd Ack; Removing MessageCounter:21480352 from Retrans Table on exchange 56103r
[51630[D][DMG]Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
[51631[D][DMG]RE:Run Cluster 45, Attribute 0 is dirty
[51632[D][DMG]Reading attribute: Cluster=0x0000_0045 Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
[51634[D][DMG] Sending report (payload has 39 bytes)...
[51636[P][EM]<<< [E:56104r S:19077 M:224983187 (Ack:205398527)] (S) Msg TX to 1:000000000001B669 [FE15] --- Type 0001:05 (IM:ReportData)
[51638[P]IN Sending msg 224983187 on secure session with LSID: 19077
[51640[D][DMG]IM RH moving to [AwaitingReportResponse]
[51641[D][DMG] ReportsInFlight = 1 with readHandler 0, RE has no more messages
[51644[D][DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[52068[D][IN]UDP Message Received packet nb : 10 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 42
[52071[P][EM]>>> [E:56104r S:19077 M:205398528 (Ack:224983187)] (S) Msg RX from 1:000000000001B669 [FE15] --- Type 0001:01 (IM:StatusResponse)
[52073[D][EM]Found matching exchange: 56104r, Delegate: 0x4008ec4
[52074[D][EM]Rxd Ack; Removing MessageCounter:224983187 from Retrans Table on exchange 56104r
[52076[P][IM]Received status response, status is 0x00
[52077[P][EM]<<< [E:56104r S:19077 M:224983188 (Ack:205398528)] (S) Msg TX to 1:000000000001B669 [FE15] --- Type 0001:04 (IM:SubscribeResponse)
[52080[P]IN Sending msg 224983188 on secure session with LSID: 19077
[52082[P][DMG]Registered a ReadHandler that will schedule a report between system Timestamp: lu and system Timestamp lu.
[52083[D][DMG] OnReportConfirm: NumReports = 0
[52084[D][DMG]IM RH moving to [CanStartReporting]
▒[52318[D][IN]UDP Message Received packet nb : 11 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 34
[52321[P][EM]>>> [E:56104r S:19077 M:205398529 (Ack:224983188)] (S) Msg RX from 1:000000000001B669 [FE15] --- Type 0000:10 (SecureChannel:StandaloneAck)
[52323[D][EM]Found matching exchange: 56104r, Delegate: 0
[52324[D][EM]Rxd Ack; Removing MessageCounter:224983188 from Retrans Table on exchange 56104r
[56327[P][DL]OpenThread SED interval is 5000ms
// restart the device
[0[D][ini]==================================================
[0[D][ini]Matter Accessory Starting
[0[D][ini]==================================================
[0[D][ini]Init CHIP Stack
Device_MAC_ID = 18:c2:3c:22:c3:8d
[115[D][ini]Init OpenThread Stack
[197[P][DL]OpenThread SED interval is 5000ms
[200[P][DL]OpenThread ifconfig up and thread start
[208[P][DL]KVS, Matter key [g/fs/n] not found in persistent storage.
[209[P][DL]OpenThread started: OK
[210[P][DL]Setting OpenThread device type to SLEEPY END DEVICE
[212[D][DL]Thread task running
[215[D][DL]CHIP event task running
[215[D][DL]OpenThread State Changed (Flags: 0x1117d33d)
[216[D][DL] Device Role: DETACHED
[217[D][DL] Network Name: OpenThreadDemo
[218[D][DL] PAN Id: 0x6666
[219[D][DL] Extended PAN Id: 0x1111116666223344
[220[D][DL] Channel: 16
[221[D][DL] Mesh Prefix: fd29:119e:23dc:90e8:0:0:0:0/64
[221[D][DL] Thread Unicast Addresses:
[222[D][DL] fd29:119e:23dc:90e8:0:ff:fe00:182f/64 valid rloc
[224[D][DL] fd29:119e:23dc:90e8:c57e:3ecb:cc49:16a7/64 valid
[225[D][DL] fe80:0:0:0:8830:e1eb:4252:bef4/64 valid preferred
[227[D][ini]Init Matter Server
[228[P][SVR]Initializing subscription resumption storage...
[229[P][DL]KVS, get the value of Matter key [g/sum] with PDM id: 1280
[230[P][DL]KVS, save in flash the value of the Matter key [g/sum] with PDM id: 1280
[231[P][SVR]Server initializing...
[232[D][FP]Initializing FabricTable from persistent storage
[233[P][DL]KVS, get the value of Matter key [g/lkgt] with PDM id: 1281
[234[P][TS]Last Known Good Time: 2023-08-23T12:10:48
[236[P][DL]KVS, get the value of Matter key [g/fidx] with PDM id: 1299
[238[P][DL]KVS, get the value of Matter key [f/1/n] with PDM id: 1296
[240[P][DL]KVS, get the value of Matter key [f/1/r] with PDM id: 1298
[244[P][DL]KVS, get the value of Matter key [f/1/m] with PDM id: 1294
[245[P][FP]Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xA612970B973EFE15, FabricId 0x0000000000000001, NodeId 0x0000000000000001, VendorId 0xFFF1
[254[P][DL]KVS, Matter key [g/fs/c] not found in persistent storage.
[255[P][DMG]AccessControl: initializing
[256[P][DMG]Examples::AccessControlDelegate::Init
[256[P][DMG]AccessControl: setting
[257[P][DMG]DefaultAclStorage: initializing
[258[P][DL]KVS, get the value of Matter key [f/1/ac/0/0] with PDM id: 1288
[266[P][DL]KVS, Matter key [f/1/ac/0/1] not found in persistent storage.
[267[P][DMG]DefaultAclStorage: 1 entries loaded
[268[D][IN]UDP::Init bind&listen port=5540
[269[D][IN]UDP::Init bound to port=5540
[270[D][IN]BLEBase::Init - setting/overriding transport
[270[D][IN]TransportMgr initialized
[272[P][DL]KVS, get the value of Matter key [g/gcc] with PDM id: 1282
[273[P][DL]KVS, get the value of Matter key [g/gdc] with PDM id: 1283
[274[P][DL]KVS, save in flash the value of the Matter key [g/gcc] with PDM id: 1282
[276[P][DL]KVS, save in flash the value of the Matter key [g/gdc] with PDM id: 1283
[278[D][DL]Using Thread extended MAC for hostname.
[279[P][DL]KVS, get the value of Matter key [g/im/ec] with PDM id: 1284
[281[P][DL]KVS, save in flash the value of the Matter key [g/im/ec] with PDM id: 1284
[282[P][ZCL]Using ZAP configuration...
[290[P][DL]KVS, Matter key [g/a/0/28/5] not found in persistent storage.
[291[D][DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
[299[P][DL]KVS, Matter key [g/a/0/28/10] not found in persistent storage.
[300[D][DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0
[306[P][DMG]AccessControlCluster: initializing
[306[P][ZCL]Initiating Admin Commissioning cluster.
[307[D][DMG]Endpoint 0, Cluster 0x0000_0030 update version to 8904be3
[308[D][ZCL]GeneralDiagnostics: OnDeviceReboot
[309[D][DMG]Endpoint 0, Cluster 0x0000_0033 update version to c6f5f88b
[311[D][EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000004E
[318[P][SVR]Fabric already commissioned. Disabling BLE advertisement
[320[P][DIS]Updating services using commissioning mode 0
[320[D][DL]Using Thread extended MAC for hostname.
[321[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[323[D][DL]Using Thread extended MAC for hostname.
[323[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=0
[325[D][DIS]Scheduling extended discovery timeout in 86400s
[326[P][DIS]Delaying proxy of operational discovery: missing delegate
[328[P][IN]CASE Server enabling CASE session setups
[330[D][IN]SecureSession[0x400e9c8]: Allocated Type:2 LSID:31836
[331[D][SC]Allocated SecureSession (0x400e9c8) - waiting for Sigma1 msg
[332[D][ZCL]Emitting StartUp event
[333[D][EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000065
[336[P][SVR]Server Listening...
[337[D][DL]OpenThread State Changed (Flags: 0x00000084)
[338[D][DL] Device Role: CHILD
[338[D][DL] Partition Id: 0x34C3B39C
[340[D][ini]Initialize device attestation config
[340[P][SVR]SetupQRCode: [MT:6FCJ10ID00G60648G00]
[341[P][SVR]Copy/paste the below URL in a browser to see the QR Code:
[342[P][SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ10ID00G60648G00
[344[P][SVR]Manual pairing code: [633317123365521327730]
█▀▀▀▀▀█ ▀▀ ▄█▄▄▀▀ █ █▀▀▀▀▀█
█ ███ █ ▄█▀██ █▀█▄ ▀ █ ███ █
█ ▀▀▀ █ ▄▄ ▄▀▀█ ▄ ▀ █ ▀▀▀ █
▀▀▀▀▀▀▀ ▀▄▀▄▀▄▀▄█▄█▄▀ ▀▀▀▀▀▀▀
▄▄▀▄█▀▀ ▀ ▀ █▀▀ ▄█▄ ▀ ▄ █ █
▄▀ ▀▀ ▀ ▀▀ ▄██▀▀ ▄▄ ▄▀█▀▄▀ ▄
▀█▀ █▄▀▀▄█▄ ▀▀▀▄██▄█ ▀ █ █▀▄
▀▀▀ ███▀▀▄▄▀█ ▄▄▀█▄▄▄█▄█▄
▀ █ ▀▀▀▀██ ▄▄█▄▄█▄▄██ █▄▀ █
▀▄▄█▀ ▀ █ ▄▄ █▀▀█▄█ ▄▄▀ █
▀ ▀ ▀▀ █ ▄ █▄▄ █ ██▀▀▀█ ▀▄▄
█▀▀▀▀▀█ ▄ ▄█▄ ▄▀ ███ ▀ █▄█ ▀
█ ███ █ ▀█ ▄ ▀▀ ▄ ▀▀▀▀▀▄ ▄▀
█ ▀▀▀ █ ▀███▄▀▀▀▄█▄ ▄▀▀▄▄▀▄█
▀▀▀▀▀▀▀ ▀ ▀ ▀ ▀▀ ▀▀▀ ▀ ▀
[513[D][ZCL]GeneralDiagnostics: OnHardwareFaultsDetect
[514[D][DMG]Endpoint 0, Cluster 0x0000_0033 update version to c6f5f88c
[522[P][DL]SRP Client was started, detected server: fd29:119e:23dc:90e8:2570:188b:16e3:8234
[519[D][EVL]LogEvent event number: 0x0000000000010002 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x0 Sys timestamp: 0x000000000000011F
[527[D][DL]OpenThread State Changed (Flags: 0x00000200)
[528[D][DL]Thread Attached updating Multicast address
[529[P][SVR]Joining Multicast groups
[530[P][DL]KVS, get the value of Matter key [f/1/g] with PDM id: 1287
[531[D][DL]OpenThread State Changed (Flags: 0x00000001)
[532[D][DL] Thread Unicast Addresses:
[533[D][DL] fde5:4e59:fb89:1:5652:5490:efa4:8f40/64 valid preferred
[535[D][DL] fd29:119e:23dc:90e8:0:ff:fe00:182f/64 valid rloc
[536[D][DL] fd29:119e:23dc:90e8:c57e:3ecb:cc49:16a7/64 valid
[538[D][DL] fe80:0:0:0:8830:e1eb:4252:bef4/64 valid preferred
[1361[D][DL]SRP update succeeded
[1361[P][DIS]Setting operational delegate post init
[1362[P][SVR]Server initialization complete
[1363[P][DIS]Updating services using commissioning mode 0
[1364[D][DL]Using Thread extended MAC for hostname.
[1365[P][DIS]Advertise operational node A612970B973EFE15-0000000000000001
[1367[P][DL]advertising srp service: A612970B973EFE15-0000000000000001._matter._tcp
[1368[D][DL]Using Thread extended MAC for hostname.
[1369[P][DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=2592/10 cm=0
[1372[P][DL]advertising srp service: 6FE3ED19B1948168._matterc._udp
[1374[P][DL]KVS, get the value of Matter key [g/su/0] with PDM id: 1291
[1382[P][DL]KVS, Matter key [g/su/1] not found in persistent storage.
[1390[P][DL]KVS, Matter key [g/su/2] not found in persistent storage.
[1398[P][DL]KVS, Matter key [g/su/3] not found in persistent storage.
[1406[P][DL]KVS, Matter key [g/su/4] not found in persistent storage.
[1413[P][DL]KVS, Matter key [g/su/5] not found in persistent storage.
[1415[P][IM]Resuming 1 subscriptions in 0 seconds
[1416[P][DL]KVS, get the value of Matter key [g/su/0] with PDM id: 1291
[1418[P][IM]Resuming subscriptionId 2152605653
[1418[D][CSM]FindOrEstablishSession: PeerId = [1:000000000001B669]
[1420[D][CSM]FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1421[D][DIS]OperationalSessionSetup[1:000000000001B669]: State change 1 --> 2
[1422[P][DIS]Resolving A612970B973EFE15:000000000001B669 ...
[1432[P][DL]KVS, Matter key [g/su/1] not found in persistent storage.
[1440[P][DL]KVS, Matter key [g/su/2] not found in persistent storage.
[1450[P][DL]KVS, Matter key [g/su/3] not found in persistent storage.
[1458[P][DL]KVS, Matter key [g/su/4] not found in persistent storage.
[1468[P][DL]KVS, Matter key [g/su/5] not found in persistent storage.
[1593[P][gb]Generic Behavior, Device state move to END ,last state is INIT
[1594[P][gb]Device commission to fabric already!Go to Idle state
[1595[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee9227
[1596[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee9228
[1598[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee9229
[1599[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922a
[1600[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922b
[1602[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922c
[1603[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922d
[1604[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922e
[1622[P][DIS]Checking node lookup status after 200 ms
[1656[P][enm]Update the device's voltage (3311)
[1657[P][enm]Update the device's remain percent (200)
[1658[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee922f
[1660[D][DMG]Endpoint 2, Cluster 0x0000_002F update version to 44ee9230
[2023[P][DIS]Node ID resolved for A612970B973EFE15:000000000001B669
[2024[D][DIS] Hostname: DCA632F395430000
[2025[D][DIS] IP Address #1: fd11:1111:6666:3344:dea6:32ff:fef3:9542
[2027[D][DIS] Port: 55500
[2028[D][DIS] Mrp Interval idle: not present
[2029[D][DIS] Mrp Interval active: not present
[2029[D][DIS] TCP Supported: 1
[2030[D][DIS]Lookup clearing interface for non LL address
[2032[P][DIS]UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542]:55500: new best score: 3
[2033[P][DIS]Checking node lookup status after 611 ms
[2036[D][DIS]OperationalSessionSetup[1:000000000001B669]: Updating device address to UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542]:55500 while in state 2
[2039[D][DIS]OperationalSessionSetup[1:000000000001B669]: State change 2 --> 3
[2041[D][IN]SecureSession[0x400ea88]: Allocated Type:2 LSID:31837
[2044[P][SC]Initiating session on local FabricIndex 1 from 0x0000000000000001 -> 0x000000000001B669
[2060[P][DL]KVS, get the value of Matter key [f/1/g] with PDM id: 1287
[2062[P][DL]KVS, get the value of Matter key [f/1/k/0] with PDM id: 1285
[2067[D][SC]Including MRP parameters
[2068[P][DL]KVS, get the value of Matter key [f/1/s/000000000001B669] with PDM id: 1290
[2071[P][EM]<<< [E:43932i S:0 M:117714684] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[2074[P]IN Sending msg 117714684 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542]:55500'
[2076[P][DL]OpenThread SED interval is 250ms
[2077[P][SC]Sent Sigma1 msg
[2077[D][DIS]OperationalSessionSetup[1:000000000001B669]: State change 3 --> 4
[2425[D][IN]UDP Message Received packet nb : 1 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 70
[2428[P][EM]>>> [E:43932i S:0 M:128469503 (Ack:117714684)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
[2430[D][EM]Found matching exchange: 43932i, Delegate: 0x400f34c
[2431[D][EM]Rxd Ack; Removing MessageCounter:117714684 from Retrans Table on exchange 43932i
[2433[P][EM]<<< [E:43932i S:0 M:117714685 (Ack:128469503)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[2436[P]IN Sending msg 117714685 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[2438[D][EM]Flushed pending ack for MessageCounter:128469503 on exchange 43932i
[2439[D][SC]Received Sigma2Resume msg
[2441[D][SC]Peer assigned session session ID 51255
[2443[P][DL]KVS, get the value of Matter key [g/sri] with PDM id: 1292
[2444[P][DL]KVS, get the value of Matter key [f/1/s/000000000001B669] with PDM id: 1290
[2446[P][DL]KVS, delete from flash the Matter key [g/s/co6Pf5P2fjnRJZKwYsXWaQ==] with PDM id: 1033
[2448[P][DL]KVS, delete from flash the value of the Matter key [g/s/co6Pf5P2fjnRJZKwYsXWaQ==] with PDM id: 1289
[2450[P][DL]KVS, save in flash the value of the Matter key [f/1/s/000000000001B669] with PDM id: 1290
[2459[P][DL]KVS, save in flash the value of the Matter key [g/s/soRVU7pcT3siAKo88tpDJg==] with PDM id: 1289
[2461[P][DL]KVS, save in flash the Matter key [g/s/soRVU7pcT3siAKo88tpDJg==] with PDM id: 1033 and length 29
[2463[D][SC]Sending status report. Protocol code 0, exchange 43932
[2464[P][EM]<<< [E:43932i S:0 M:117714686 (Ack:128469503)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[2467[P]IN Sending msg 117714686 to IP address 'UDP:[fd11:1111:6666:3344:dea6:32ff:fef3:9542%ot]:55500'
[2470[P][SC]SecureSession[0x400ea88, LSID:31837]: State change 'kEstablishing' --> 'kActive'
[2474[D][IN]SecureSession[0x400ea88]: Activated - Type:2 LSID:31837
[2475[D][IN]New secure session activated for device <000000000001B669, 1>, LSID:31837 PSID:51255!
[2476[D][DIS]OperationalSessionSetup[1:000000000001B669]: State change 4 --> 5
[2478[D][DMG]IM RH moving to [CanStartReporting]
[2479[D][DMG]Cannot merge the new path into any existing path, create one.
[2617[D][IN]UDP Message Received packet nb : 2 SrcAddr : fd11:1111:6666:3344:dea6:32ff:fef3:9542[55500] DestAddr : fde5:4e59:fb89:1:5652:5490:efa4:8f40[5540] Payload Length 26
[2620[P][EM]>>> [E:43932i S:0 M:128469504 (Ack:117714686)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[2622[D][EM]Found matching exchange: 43932i, Delegate: 0
[2623[D][EM]Rxd Ack; Removing MessageCounter:117714686 from Retrans Table on exchange 43932i
[2997[D][DL]SRP update succeeded
[6630[P][DL]OpenThread SED interval is 5000ms
Bug prevalence
Whenever i do this
GitHub hash of the SDK that was being used
1df99a9
Platform
core
Platform Version(s)
No response
Anything else?
No response
The text was updated successfully, but these errors were encountered: