search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.34k stars 1.97k forks source link

[1.0] Device seen offline after successful commissioning with Google Home App #23761

Closed FutronicsMP closed 11 months ago

FutronicsMP commented 1 year ago

Reproduction steps

After commissioning my device is seen in Google Home App but I cannot control them as device is seen offline (not active in similar way like not powered up). Device is 30cm away from Border Router. Both Phone and Nest Hub 2 are on the same WiFi network. Phone and Nest Hub 2 are using the same google account (e-mail).

I configured aswell google project as described here: https://developers.home.google.com/matter/project/create

and configured matter integration: LigtBulb Light 0xfff1 0x8005

Does anybody have similar Issue? What might be wrong?

Problem exists for both Nordic and Silicon Labs Matter Light Examples. Enclosed please find log file from Matter Device.

Bug prevalence

Every time after successful commissioning

GitHub hash of the SDK that was being used

Nordik SDK 2.1.2 supporting Matter 1.0

Platform

efr32

Platform Version(s)

1.0

Type

Test Improvement

Anything else?

log matter (1).txt

mcreteau commented 1 year ago

Hello Yes I experience the same issue while using a Matter Bridge commissioned by Google Home app. Bridge is displayed but underlying devices are offline.

rochaferraz commented 1 year ago

Hi @FutronicsMP. Thanks for raising the issue. We've identified a relevant cloud flag that hasn't fully rolled out yet that's preventing control. We will work on expediting it.

FutronicsMP commented 1 year ago

@rochaferraz Thank you very much for your kind answer! I was trying to get help regarding that from Silicon Labs and Nordic and for at least 2 days trying to make it work. You save my next day :) Do you know when it's planned to release of an improved version?

benjaminnestler commented 1 year ago

Same for me with the Nordic Semiconductor Matter-Template extended with thermostat cluster.

@rochaferraz Is your finding a GHA bug or a bug in the Matter/connectedhomeip repository? Thanks for your great support.

doublemis1 commented 1 year ago

@FutronicsMP please try to factory reset the nest hub, remove the devices from the Google home app and link the nest once again with Google Home app, and proceed the commissioning (after commissioning Google Home App may need some time - couple seconds to have fully operational device). I tested that with Nordic, and I saw that after update of Nest Hub firmware I needed to factory reset the Hub.

FutronicsMP commented 1 year ago

@doublemis1 I did it once again today:

Both phone and Nest Hub Gen.2 are connected to the same EERO WiFi router. Google account- the same e-mail address for both phone and Nest Hub Gen.2 Below is my google integration config.

image

@rochaferraz mention that some cloud flags are not set correctly. I would like to learn more about it - I will be appreciated for sending me the issue link if there is created.

FutronicsMP commented 1 year ago

Just now installed fresh Nordic SDK v2.2.0-rc1. Still, the device is offline after successful commissioning. Looks like the flags mentioned by @rochaferraz are still not fixed. Does anybody know where I can find information on how I can fix device's offline problem?

Nest Hub 2 software version is: 47.9.4.447810048

Chromecast firmware version: 1.56.324896

Google Home App Versoin: 2.60.1.22

Nordic Light Example from SDK 2.1.2

nRF5340 Board Matter 1.0 Light_Bulb example.

`

uart:~$ I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 0, fe8 I: data wra: 0, 0 Booting Zephyr OS build v3.2.99-ncs1-rc1 I: Init CHIP stack I: 493 [DL]BLE address: DB:98:BC:80:56:3E I: 515 [DL]OpenThread started: OK I: 518 [DL]Setting OpenThread device type to ROUTER I: 523 [SVR]Server initializing... D: 526 [FP]Initializing FabricTable from persistent storage I: 532 [TS]Last Known Good Time: [unknown] I: 536 [TS]Setting Last Known Good Time to firmware build time 2022-11-28T22:24:32 I: 544 [DMG]AccessControl: initializing I: 547 [DMG]Examples::AccessControlDelegate::Init I: 552 [DMG]AccessControl: setting I: 555 [DMG]DefaultAclStorage: initializing I: 559 [DMG]DefaultAclStorage: 0 entries loaded D: 563 [IN]UDP::Init bind&listen port=5540 E: 567 [IN]SO_REUSEPORT failed: 109 D: 571 [IN]UDP::Init bound to port=5540 D: 574 [IN]BLEBase::Init - setting/overriding transport D: 579 [IN]TransportMgr initialized D: 585 [DL]Using Thread extended MAC for hostname. I: 591 [ZCL]Using ZAP configuration... D: 595 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 D: 603 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: a0 D: 610 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0 D: 617 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: a0 D: 624 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0 I: 631 [DMG]AccessControlCluster: initializing D: 635 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685672 D: 641 [DL]Boot reason: 1 D: 644 [ZCL]GeneralDiagnostics: OnDeviceReboot D: 648 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 268fd0e8 D: 655 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000028E I: 668 [ZCL]Initiating Admin Commissioning cluster. D: 673 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 626c8919 D: 680 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 1f51a49 D: 686 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 1f51a4a I: 692 [ZCL]On/Off set value: 1 0 I: 695 [ZCL]On/off already set to new value D: 700 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fd42720 I: 706 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1 D: 712 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level D: 721 [IN]SecureSession[0x20004430]: Allocated Type:1 LSID:23688 D: 727 [SC]Assigned local session key ID 23688 D: 731 [SC]Waiting for PBKDF param request D: 735 [DL]CHIPoBLE advertising set to on I: 739 [DIS]Updating services using commissioning mode 1 D: 744 [DL]Using Thread extended MAC for hostname. D: 749 [DL]Using Thread extended MAC for hostname. I: 754 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 763 [DIS]Failed to advertise commissionable node: 3 E: 768 [DIS]Failed to finalize service update: 1c I: 772 [DIS]Updating services using commissioning mode 1 D: 777 [DL]Using Thread extended MAC for hostname. D: 782 [DL]Using Thread extended MAC for hostname. I: 787 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 796 [DIS]Failed to advertise commissionable node: 3 E: 801 [DIS]Failed to finalize service update: 1c I: 806 [DIS]Delaying proxy of operational discovery: missing delegate I: 812 [IN]CASE Server enabling CASE session setups D: 817 [IN]SecureSession[0x200044e8]: Allocated Type:2 LSID:23689 D: 823 [SC]Allocated SecureSession (0x200044e8) - waiting for Sigma1 msg I: 829 [SVR]Joining Multicast groups D: 833 [ZCL]Emitting StartUp event D: 836 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000344 I: 850 [SVR]Server Listening... I: 853 [DL]Device Configuration: I: 856 [DL] Serial Number: 11223344556677889900 I: 860 [DL] Vendor Id: 65521 (0xFFF1) I: 864 [DL] Product Id: 32773 (0x8005) I: 868 [DL] Hardware Version: 0 I: 871 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 876 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 883 [DL] Manufacturing Date: (not set) I: 887 [DL] Device Type: 65535 (0xFFFF) I: 891 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 895 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 901 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00 I: 910 [SVR]Manual pairing code: [34970112332] I: 915 [DL]CHIP task running I: 922 [DL]CHIPoBLE advertising started D: 926 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to a3dbcb10 I: 933 [ZCL]Cluster OnOff: attribute OnOff set to 0 D: 938 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fd42721 I: 944 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 D: 950 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level I: 958 [DL]NFC Tag emulation started I: 30925 [DL]CHIPoBLE advertising mode changed to slow I: 100168 [DL]BLE connection established (ConnId: 0x00) I: 100174 [DL]Current number of connections: 1/2 I: 100178 [DL]CHIPoBLE advertising stopped I: 100182 [DL]NFC Tag emulation stopped I: 100624 [DL]BLE GAP connection terminated (reason 0x2a) I: 100630 [DL]Current number of connections: 0/2 I: 100637 [DL]CHIPoBLE advertising started I: 100641 [DL]NFC Tag emulation started I: 130641 [DL]CHIPoBLE advertising mode changed to slow I: 178981 [DL]BLE connection established (ConnId: 0x00) I: 178986 [DL]Current number of connections: 1/2 I: 178991 [DL]CHIPoBLE advertising stopped I: 178995 [DL]NFC Tag emulation stopped I: 179428 [DL]BLE GAP connection terminated (reason 0x2a) I: 179433 [DL]Current number of connections: 0/2 I: 179441 [DL]CHIPoBLE advertising started I: 179445 [DL]NFC Tag emulation started I: 209444 [DL]CHIPoBLE advertising mode changed to slow I: 390034 [DL]BLE connection established (ConnId: 0x00) I: 390039 [DL]Current number of connections: 1/2 I: 390044 [DL]CHIPoBLE advertising stopped I: 390048 [DL]NFC Tag emulation stopped I: 390499 [DL]BLE GAP connection terminated (reason 0x2a) I: 390504 [DL]Current number of connections: 0/2 I: 390512 [DL]CHIPoBLE advertising started I: 390516 [DL]NFC Tag emulation started I: 420516 [DL]CHIPoBLE advertising mode changed to slow I: 537740 [DL]BLE connection established (ConnId: 0x00) I: 537746 [DL]Current number of connections: 1/2 I: 537750 [DL]CHIPoBLE advertising stopped I: 537754 [DL]NFC Tag emulation stopped I: 541107 [DL]BLE GAP connection terminated (reason 0x13) I: 541112 [DL]Current number of connections: 0/2 I: 541119 [DL]CHIPoBLE advertising started I: 541124 [DL]NFC Tag emulation started I: 541577 [DL]BLE connection established (ConnId: 0x00) I: 541583 [DL]Current number of connections: 1/2 I: 541587 [DL]CHIPoBLE advertising stopped I: 541591 [DL]NFC Tag emulation stopped I: 544957 [DL]BLE GAP connection terminated (reason 0x13) I: 544962 [DL]Current number of connections: 0/2 I: 544969 [DL]CHIPoBLE advertising started I: 544974 [DL]NFC Tag emulation started I: 557881 [DL]BLE connection established (ConnId: 0x00) I: 557886 [DL]Current number of connections: 1/2 I: 557891 [DL]CHIPoBLE advertising stopped I: 557895 [DL]NFC Tag emulation stopped I: 561215 [DL]BLE GAP connection terminated (reason 0x13) I: 561220 [DL]Current number of connections: 0/2 I: 561227 [DL]CHIPoBLE advertising started I: 561231 [DL]NFC Tag emulation started I: 561517 [DL]BLE connection established (ConnId: 0x00) I: 561523 [DL]Current number of connections: 1/2 I: 561527 [DL]CHIPoBLE advertising stopped I: 561531 [DL]NFC Tag emulation stopped I: 564872 [DL]BLE GAP connection terminated (reason 0x13) I: 564877 [DL]Current number of connections: 0/2 I: 564885 [DL]CHIPoBLE advertising started I: 564889 [DL]NFC Tag emulation started I: 565912 [DL]BLE connection established (ConnId: 0x00) I: 565918 [DL]Current number of connections: 1/2 I: 565922 [DL]CHIPoBLE advertising stopped I: 565926 [DL]NFC Tag emulation stopped I: 569247 [DL]BLE GAP connection terminated (reason 0x13) I: 569252 [DL]Current number of connections: 0/2 I: 569260 [DL]CHIPoBLE advertising started I: 569264 [DL]NFC Tag emulation started I: 599264 [DL]CHIPoBLE advertising mode changed to slow I: 601294 [DL]BLE connection established (ConnId: 0x00) I: 601299 [DL]Current number of connections: 1/2 I: 601303 [DL]CHIPoBLE advertising stopped I: 601307 [DL]NFC Tag emulation stopped I: 601728 [DL]BLE GAP connection terminated (reason 0x2a) I: 601733 [DL]Current number of connections: 0/2 I: 601741 [DL]CHIPoBLE advertising started I: 601745 [DL]NFC Tag emulation started I: 631744 [DL]CHIPoBLE advertising mode changed to slow I: 900720 [SVR]Closing pairing window D: 900724 [IN]SecureSession[0x20004430]: Released - Type:1 LSID:23688 I: 900730 [DIS]Updating services using commissioning mode 0 D: 900735 [DL]Using Thread extended MAC for hostname. D: 900740 [DL]Using Thread extended MAC for hostname. I: 900746 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 900755 [DIS]Failed to advertise extended commissionable node: 3 D: 900761 [DIS]Scheduling extended discovery timeout in 900s E: 900766 [DIS]Failed to finalize service update: 1c D: 900771 [DL]CHIPoBLE advertising set to off I: 900776 [DL]CHIPoBLE advertising stopped I: 900780 [DL]NFC Tag emulation stopped I: Software update is disabled D: 948716 [IN]SecureSession[0x20004430]: Allocated Type:1 LSID:23690 D: 948722 [SC]Assigned local session key ID 23690 D: 948727 [SC]Waiting for PBKDF param request D: 948731 [DL]CHIPoBLE advertising set to on I: 948735 [DIS]Updating services using commissioning mode 1 D: 948740 [DL]Using Thread extended MAC for hostname. D: 948746 [DL]Using Thread extended MAC for hostname. I: 948751 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 948760 [DIS]Failed to advertise commissionable node: 3 E: 948765 [DIS]Failed to finalize service update: 1c I: 948773 [DL]CHIPoBLE advertising started I: 948778 [DL]NFC Tag emulation started I: 949216 [DL]BLE connection established (ConnId: 0x00) I: 949221 [DL]Current number of connections: 1/2 I: 949226 [DL]CHIPoBLE advertising stopped I: 949230 [DL]NFC Tag emulation stopped I: 949669 [DL]BLE GAP connection terminated (reason 0x2a) I: 949674 [DL]Current number of connections: 0/2 I: 949682 [DL]CHIPoBLE advertising started I: 949686 [DL]NFC Tag emulation started I: 979685 [DL]CHIPoBLE advertising mode changed to slow I: 994467 [DL]BLE connection established (ConnId: 0x00) I: 994473 [DL]Current number of connections: 1/2 I: 994477 [DL]CHIPoBLE advertising stopped I: 994481 [DL]NFC Tag emulation stopped D: 995537 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 995545 [BLE]local and remote recv window sizes = 5 I: 995550 [BLE]selected BTP version 4 I: 995553 [BLE]using BTP fragment sizes rx 128 / tx 128. D: 995572 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 995577 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 995585 [IN]BLE EndPoint 0x2000b0e8 Connection Complete I: 995590 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) D: 995677 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 995748 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 995755 [EM]>>> [E:14522r M:132793805] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) D: 995767 [EM]Handling via exchange: 14522r, Delegate: 0x20006614 D: 995773 [SC]Received PBKDF param request D: 995777 [SC]Peer assigned session ID 49619 D: 995781 [SC]Found MRP parameters in the message D: 995786 [SC]Including MRP parameters in PBKDF param response I: 995792 [EM]<<< [E:14522r M:260362351] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 995804 IN Sending msg 260362351 to IP address 'BLE' D: 995809 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 995817 [SC]Sent PBKDF param response D: 995887 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 995895 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14) D: 995957 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 995966 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 995973 [EM]>>> [E:14522r M:132793806] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) D: 995984 [EM]Found matching exchange: 14522r, Delegate: 0x20006614 D: 995990 [SC]Received spake2p msg1 I: 997547 [EM]<<< [E:14522r M:260362352] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 997558 IN Sending msg 260362352 to IP address 'BLE' D: 997564 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 997572 [SC]Sent spake2p msg2 E: 997574 [DL]Long dispatch time: 1609 ms, for event type 16388 D: 997637 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 997645 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 997707 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 997716 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 997723 [EM]>>> [E:14522r M:132793807] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) D: 997734 [EM]Found matching exchange: 14522r, Delegate: 0x20006614 D: 997740 [SC]Received spake2p msg3 D: 997744 [SC]Sending status report. Protocol code 0, exchange 14522 I: 997750 [EM]<<< [E:14522r M:260362353] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 997762 IN Sending msg 260362353 to IP address 'BLE' D: 997767 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 997775 [SC]SecureSession[0x20004430]: Moving from state 'kEstablishing' --> 'kActive' D: 997784 [IN]SecureSession[0x20004430]: Activated - Type:1 LSID:23690 D: 997790 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:23690 PSID:49619! I: 997799 [SVR]Commissioning completed session establishment step I: 997805 [DIS]Updating services using commissioning mode 0 D: 997810 [DL]Using Thread extended MAC for hostname. D: 997816 [DL]Using Thread extended MAC for hostname. I: 997822 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 997831 [DIS]Failed to advertise extended commissionable node: 3 D: 997837 [DIS]Scheduling extended discovery timeout in 900s E: 997842 [DIS]Failed to finalize service update: 1c D: 997847 [DL]CHIPoBLE advertising set to off I: 997851 [SVR]Device completed Rendezvous process E: 997856 [DL]Long dispatch time: 141 ms, for event type 16388 D: 997861 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 997869 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 997877 [EM]>>> [E:14523r M:90317629] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 997888 [EM]Handling via exchange: 14523r, Delegate: 0x20008ab4 D: 997893 [IM]Received Read request D: 997897 [DMG]IM RH moving to [GeneratingReports] D: 997902 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 997911 [DMG] Cluster 28, Attribute 2 is dirty D: 997916 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 997925 [DMG] Sending report (payload has 37 bytes)... I: 997931 [EM]<<< [E:14523r M:133783967] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 997941 IN Sending msg 133783967 on secure session with LSID: 23690 D: 997948 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 997956 [DMG] OnReportConfirm: NumReports = 0 D: 997960 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 997968 [DMG]IM RH moving to [AwaitingDestruction] D: 997972 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998022 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998031 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 998039 [EM]>>> [E:14524r M:90317630] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 998049 [EM]Handling via exchange: 14524r, Delegate: 0x20008ab4 D: 998055 [IM]Received Read request D: 998059 [DMG]IM RH moving to [GeneratingReports] D: 998063 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 998072 [DMG] Cluster 28, Attribute 4 is dirty D: 998077 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 998086 [DMG] Sending report (payload has 37 bytes)... I: 998093 [EM]<<< [E:14524r M:133783968] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 998103 IN Sending msg 133783968 on secure session with LSID: 23690 D: 998109 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 998117 [DMG] OnReportConfirm: NumReports = 0 D: 998122 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 998129 [DMG]IM RH moving to [AwaitingDestruction] D: 998134 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998162 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998171 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 998179 [EM]>>> [E:14525r M:90317631] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 998189 [EM]Handling via exchange: 14525r, Delegate: 0x20008ab4 D: 998195 [IM]Received Read request D: 998199 [DMG]IM RH moving to [GeneratingReports] D: 998203 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 998212 [DMG] Cluster 3e, Attribute 2 is dirty D: 998217 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 998226 [DMG] Sending report (payload has 36 bytes)... I: 998233 [EM]<<< [E:14525r M:133783969] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 998243 IN Sending msg 133783969 on secure session with LSID: 23690 D: 998249 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 998257 [DMG] OnReportConfirm: NumReports = 0 D: 998262 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 998269 [DMG]IM RH moving to [AwaitingDestruction] D: 998274 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998302 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998311 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 998319 [EM]>>> [E:14526r M:90317632] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 998329 [EM]Handling via exchange: 14526r, Delegate: 0x20008ab4 D: 998335 [IM]Received Read request D: 998339 [DMG]IM RH moving to [GeneratingReports] D: 998343 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 998352 [DMG] Cluster 3e, Attribute 3 is dirty D: 998357 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 998366 [DMG] Sending report (payload has 36 bytes)... I: 998373 [EM]<<< [E:14526r M:133783970] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 998383 IN Sending msg 133783970 on secure session with LSID: 23690 D: 998389 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 998397 [DMG] OnReportConfirm: NumReports = 0 D: 998402 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 998409 [DMG]IM RH moving to [AwaitingDestruction] D: 998414 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998442 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998451 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 998459 [EM]>>> [E:14527r M:90317633] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 998469 [EM]Handling via exchange: 14527r, Delegate: 0x20008ab4 D: 998475 [IM]Received Read request D: 998479 [DMG]IM RH moving to [GeneratingReports] D: 998483 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 998492 [DMG] Cluster 3e, Attribute 1 is dirty D: 998497 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 998506 [DMG] Sending report (payload has 36 bytes)... I: 998513 [EM]<<< [E:14527r M:133783971] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 998523 IN Sending msg 133783971 on secure session with LSID: 23690 D: 998529 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 998537 [DMG] OnReportConfirm: NumReports = 0 D: 998542 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 998549 [DMG]IM RH moving to [AwaitingDestruction] D: 998554 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998582 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998591 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 998599 [EM]>>> [E:14528r M:90317634] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 998609 [EM]Handling via exchange: 14528r, Delegate: 0x20008ab4 D: 998615 [IM]Received Read request D: 998619 [DMG]IM RH moving to [GeneratingReports] D: 998623 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 998632 [DMG] Cluster 1d, Attribute 1 is dirty D: 998637 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 998647 [DMG] Sending report (payload has 400 bytes)... I: 998655 [EM]<<< [E:14528r M:133783972] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 998665 IN Sending msg 133783972 on secure session with LSID: 23690 D: 998672 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 998679 [DMG] OnReportConfirm: NumReports = 0 D: 998684 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 998692 [DMG]IM RH moving to [AwaitingDestruction] D: 998696 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 998722 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998730 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 998792 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998800 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 998862 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998870 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57) D: 998933 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 998941 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 999003 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 999011 [EM]>>> [E:14529r M:90317635] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 999021 [EM]Handling via exchange: 14529r, Delegate: 0x20008ab4 D: 999027 [IM]Received Read request D: 999031 [DMG]IM RH moving to [GeneratingReports] D: 999036 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 999045 [DMG] Cluster 31, Attribute fffc is dirty D: 999050 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0) D: 999059 [DMG] Sending report (payload has 37 bytes)... I: 999065 [EM]<<< [E:14529r M:133783973] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 999075 IN Sending msg 133783973 on secure session with LSID: 23690 D: 999082 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 999090 [DMG] OnReportConfirm: NumReports = 0 D: 999095 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 999102 [DMG]IM RH moving to [AwaitingDestruction] D: 999107 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 999142 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1000870 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1000878 [EM]>>> [E:14530r M:90317636] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 1000889 [EM]Handling via exchange: 14530r, Delegate: 0x20008ab4 D: 1000895 [DMG]Got Timed Request with timeout 10000: handler 0x20008eb0 exchange 14530r I: 1000903 [EM]<<< [E:14530r M:133783974] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 1000914 IN Sending msg 133783974 on secure session with LSID: 23690 D: 1000921 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 1000928 [DMG]Timed Request time limit 0x00000000000F6CF0: handler 0x20008eb0 exchange 14530r D: 1001005 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001013 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1001021 [EM]>>> [E:14530r M:90317637] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1001032 [EM]Found matching exchange: 14530r, Delegate: 0x20008eb0 D: 1001039 [DMG]Timed following action arrived at 0x00000000000F464F: handler 0x20008eb0 exchange 14530r D: 1001048 [DMG]Handing timed invoke to IM engine: handler 0x20008eb0 exchange 14530r D: 1001056 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 I: 1001064 [FS]GeneralCommissioning: Received ArmFailSafe (120s) D: 1001070 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685673 D: 1001077 [DMG]Command handler moving to [ Preparing] D: 1001081 [DMG]Command handler moving to [AddingComm] D: 1001086 [DMG]Command handler moving to [AddedComma] D: 1001091 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1001099 [EM]<<< [E:14530r M:133783975] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1001110 IN Sending msg 133783975 on secure session with LSID: 23690 D: 1001117 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1001125 [DMG]Command handler moving to [CommandSen] D: 1001130 [DMG]Command handler moving to [AwaitingDe] E: 1001135 [DL]Long dispatch time: 121 ms, for event type 16388 D: 1001185 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001193 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1001201 [EM]>>> [E:14531r M:90317638] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 1001212 [EM]Handling via exchange: 14531r, Delegate: 0x20008ab4 D: 1001218 [IM]Received Read request D: 1001222 [DMG]IM RH moving to [GeneratingReports] D: 1001226 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1001235 [DMG] Cluster 30, Attribute 3 is dirty D: 1001240 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 1001250 [DMG] Sending report (payload has 36 bytes)... I: 1001256 [EM]<<< [E:14531r M:133783976] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 1001266 IN Sending msg 133783976 on secure session with LSID: 23690 D: 1001273 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1001281 [DMG] OnReportConfirm: NumReports = 0 D: 1001286 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1001293 [DMG]IM RH moving to [AwaitingDestruction] D: 1001298 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 1001365 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001373 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1001381 [EM]>>> [E:14532r M:90317639] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 1001392 [EM]Handling via exchange: 14532r, Delegate: 0x20008ab4 D: 1001398 [DMG]Got Timed Request with timeout 10000: handler 0x20008eb0 exchange 14532r I: 1001406 [EM]<<< [E:14532r M:133783977] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 1001417 IN Sending msg 133783977 on secure session with LSID: 23690 D: 1001424 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 1001431 [DMG]Timed Request time limit 0x00000000000F6EE7: handler 0x20008eb0 exchange 14532r D: 1001500 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001508 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1001516 [EM]>>> [E:14532r M:90317640] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1001528 [EM]Found matching exchange: 14532r, Delegate: 0x20008eb0 D: 1001534 [DMG]Timed following action arrived at 0x00000000000F483E: handler 0x20008eb0 exchange 14532r D: 1001543 [DMG]Handing timed invoke to IM engine: handler 0x20008eb0 exchange 14532r D: 1001551 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 1001561 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685674 D: 1001568 [DMG]Command handler moving to [ Preparing] D: 1001573 [DMG]Command handler moving to [AddingComm] D: 1001578 [DMG]Command handler moving to [AddedComma] D: 1001583 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1001590 [EM]<<< [E:14532r M:133783978] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1001602 IN Sending msg 133783978 on secure session with LSID: 23690 D: 1001608 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1001616 [DMG]Command handler moving to [CommandSen] D: 1001621 [DMG]Command handler moving to [AwaitingDe] E: 1001626 [DL]Long dispatch time: 118 ms, for event type 16388 D: 1001680 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001688 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1001696 [EM]>>> [E:14533r M:90317641] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1001708 [EM]Handling via exchange: 14533r, Delegate: 0x20008ab4 D: 1001714 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 1001722 [ZCL]OpCreds: Certificate Chain request received for DAC D: 1001728 [DMG]Command handler moving to [ Preparing] D: 1001733 [DMG]Command handler moving to [AddingComm] D: 1001738 [DMG]Command handler moving to [AddedComma] D: 1001743 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1001753 [EM]<<< [E:14533r M:133783979] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1001764 IN Sending msg 133783979 on secure session with LSID: 23690 D: 1001771 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1001779 [DMG]Command handler moving to [CommandSen] D: 1001783 [DMG]Command handler moving to [AwaitingDe] D: 1001860 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001868 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1001950 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1001958 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002040 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002048 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002130 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002138 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1002146 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57) D: 1002220 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002228 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1002236 [EM]>>> [E:14534r M:90317642] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1002248 [EM]Handling via exchange: 14534r, Delegate: 0x20008ab4 D: 1002254 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 1002262 [ZCL]OpCreds: Certificate Chain request received for PAI D: 1002268 [DMG]Command handler moving to [ Preparing] D: 1002273 [DMG]Command handler moving to [AddingComm] D: 1002278 [DMG]Command handler moving to [AddedComma] D: 1002283 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1002292 [EM]<<< [E:14534r M:133783980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1002304 IN Sending msg 133783980 on secure session with LSID: 23690 D: 1002311 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002318 [DMG]Command handler moving to [CommandSen] D: 1002323 [DMG]Command handler moving to [AwaitingDe] D: 1002400 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002408 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002490 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002498 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002580 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002588 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002670 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002678 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1002686 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28) D: 1002760 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002768 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1002777 [EM]>>> [E:14535r M:90317643] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1002788 [EM]Handling via exchange: 14535r, Delegate: 0x20008ab4 D: 1002794 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 1002802 [ZCL]OpCreds: Received an AttestationRequest command I: 1002837 [ZCL]OpCreds: AttestationRequest successful. D: 1002842 [DMG]Command handler moving to [ Preparing] D: 1002847 [DMG]Command handler moving to [AddingComm] D: 1002852 [DMG]Command handler moving to [AddedComma] D: 1002857 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1002868 [EM]<<< [E:14535r M:133783981] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1002879 IN Sending msg 133783981 on secure session with LSID: 23690 D: 1002886 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1002894 [DMG]Command handler moving to [CommandSen] D: 1002899 [DMG]Command handler moving to [AwaitingDe] E: 1002904 [DL]Long dispatch time: 136 ms, for event type 16388 D: 1002985 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1002993 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003075 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003083 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003165 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003173 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003255 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003263 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1003271 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003345 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003353 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90) D: 1003435 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003443 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1003452 [EM]>>> [E:14536r M:90317644] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1003463 [EM]Handling via exchange: 14536r, Delegate: 0x20008ab4 D: 1003469 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 1003477 [ZCL]OpCreds: Received a CSRRequest command D: 1003482 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0 I: 1003646 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 1003681 [ZCL]OpCreds: CSRRequest successful. D: 1003685 [DMG]Command handler moving to [ Preparing] D: 1003690 [DMG]Command handler moving to [AddingComm] D: 1003695 [DMG]Command handler moving to [AddedComma] D: 1003700 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1003709 [EM]<<< [E:14536r M:133783982] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1003720 IN Sending msg 133783982 on secure session with LSID: 23690 D: 1003727 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003735 [DMG]Command handler moving to [CommandSen] D: 1003739 [DMG]Command handler moving to [AwaitingDe] E: 1003744 [DL]Long dispatch time: 301 ms, for event type 16388 D: 1003840 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003848 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1003930 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1003938 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 1004020 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1005281 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005371 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005461 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1005471 [EM]>>> [E:14537r M:90317645] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1005482 [EM]Handling via exchange: 14537r, Delegate: 0x20008ab4 D: 1005488 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I: 1005496 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 1005558 [ZCL]OpCreds: AddTrustedRootCertificate successful. D: 1005563 [DMG]Command handler moving to [ Preparing] D: 1005568 [DMG]Command handler moving to [AddingComm] D: 1005573 [DMG]Command handler moving to [AddedComma] D: 1005578 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1005586 [EM]<<< [E:14537r M:133783983] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1005597 IN Sending msg 133783983 on secure session with LSID: 23690 D: 1005604 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68) D: 1005612 [DMG]Command handler moving to [CommandSen] D: 1005616 [DMG]Command handler moving to [AwaitingDe] E: 1005621 [DL]Long dispatch time: 160 ms, for event type 16388 D: 1005685 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1005693 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005776 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005866 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005956 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1005964 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 1006090 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1006098 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1006181 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1006192 [EM]>>> [E:14538r M:90317646] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1006203 [EM]Handling via exchange: 14538r, Delegate: 0x20008ab4 D: 1006210 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I: 1006218 [ZCL]OpCreds: Received an AddNOC command I: 1006224 [FP]Validating NOC chain I: 1006339 [FP]NOC chain validation successful I: 1006343 [FP]Added new fabric at index: 0x1 I: 1006347 [FP]Assigned compressed fabric ID: 0xB693EC17E2AE5718, node ID: 0x00000000089EC2FD I: 1006356 [TS]Last Known Good Time: 2022-11-28T22:24:32 I: 1006361 [TS]New proposed Last Known Good Time: 2022-11-28T23:51:29 I: 1006367 [TS]Updating pending Last Known Good Time to 2022-11-28T23:51:29 D: 1006374 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517076 D: 1006381 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517077 D: 1006396 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000000F5B3C I: 1006411 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001 D: 1006420 [DL]Using Thread extended MAC for hostname. I: 1006424 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD D: 1006431 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517078 D: 1006438 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517079 D: 1006445 [DMG]Command handler moving to [ Preparing] D: 1006450 [DMG]Command handler moving to [AddingComm] D: 1006455 [DMG]Command handler moving to [AddedComma] I: 1006459 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC D: 1006466 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1006474 [EM]<<< [E:14538r M:133783984] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1006485 IN Sending msg 133783984 on secure session with LSID: 23690 D: 1006492 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1006499 [DMG]Command handler moving to [CommandSen] D: 1006504 [DMG]Command handler moving to [AwaitingDe] E: 1006509 [DL]Long dispatch time: 328 ms, for event type 16388 D: 1006585 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1006593 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1006676 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1006684 [EM]>>> [E:14539r M:90317647] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1006695 [EM]Handling via exchange: 14539r, Delegate: 0x20008ab4 D: 1006702 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003 D: 1006711 [DMG]Command handler moving to [ Preparing] D: 1006716 [DMG]Command handler moving to [AddingComm] D: 1006721 [DMG]Command handler moving to [AddedComma] D: 1006726 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685675 D: 1006733 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1006740 [EM]<<< [E:14539r M:133783985] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1006752 IN Sending msg 133783985 on secure session with LSID: 23690 D: 1006758 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1006766 [DMG]Command handler moving to [CommandSen] D: 1006771 [DMG]Command handler moving to [AwaitingDe] E: 1006776 [DL]Long dispatch time: 101 ms, for event type 16388 D: 1006855 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1006863 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1006872 [EM]>>> [E:14540r M:90317648] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:02 (IM:ReadRequest) D: 1006882 [EM]Handling via exchange: 14540r, Delegate: 0x20008ab4 D: 1006888 [IM]Received Read request D: 1006892 [DMG]IM RH moving to [GeneratingReports] D: 1006897 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1006905 [DMG] Cluster 31, Attribute 3 is dirty D: 1006911 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 1006920 [DMG] Sending report (payload has 36 bytes)... I: 1006926 [EM]<<< [E:14540r M:133783986] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:05 (IM:ReportData) I: 1006936 IN Sending msg 133783986 on secure session with LSID: 23690 D: 1006943 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 1006951 [DMG] OnReportConfirm: NumReports = 0 D: 1006956 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1006963 [DMG]IM RH moving to [AwaitingDestruction] D: 1006968 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 1007035 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1007043 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1007052 [EM]>>> [E:14541r M:90317649] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1007063 [EM]Handling via exchange: 14541r, Delegate: 0x20008ab4 D: 1007069 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 D: 1007088 [DMG]Decreasing reference count for CommandHandler, remaining 1 D: 1007094 [DL]OpenThread State Changed (Flags: 0x101fc100) D: 1007100 [DL] Network Name: NEST-PAN-ACED D: 1007104 [DL] PAN Id: 0xACED D: 1007107 [DL] Extended PAN Id: 0x2F258DB1196F8B1D D: 1007112 [DL] Channel: 14 D: 1007114 [DL] Mesh Prefix: fd98:c16c:90c1::/64 D: 1007120 [DL]OpenThread State Changed (Flags: 0x1100101d) D: 1007125 [DL] Device Role: DETACHED D: 1007129 [DL] Thread Unicast Addresses: D: 1007133 [DL] fd98:c16c:90c1:0:f87f:557f:8d2d:2755/64 valid D: 1007139 [DL] fe80::606f:a9c5:f78c:497e/64 valid preferred I: 1008295 [DL]SRP Client was started, detected server: fd98:c16c:90c1:0000:5038:2f60:4549:4783 D: 1008304 [DL]OpenThread State Changed (Flags: 0x200012a4) D: 1008309 [DL] Device Role: CHILD D: 1008312 [DL] Partition Id: 0x146288D6 D: 1008317 [DL]OpenThread State Changed (Flags: 0x00000001) D: 1008322 [DL] Thread Unicast Addresses: D: 1008326 [DL] fd86:7e7b:14e4:1:6535:eb66:a91:8bda/64 valid preferred D: 1008333 [DL] fd98:c16c:90c1::ff:fe00:3802/64 valid rloc D: 1008339 [DL] fd98:c16c:90c1:0:f87f:557f:8d2d:2755/64 valid D: 1008345 [DL] fe80::606f:a9c5:f78c:497e/64 valid preferred D: 1008352 [DMG]Command handler moving to [ Preparing] D: 1008357 [DMG]Command handler moving to [AddingComm] D: 1008362 [DMG]Command handler moving to [AddedComma] D: 1008367 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685676 D: 1008374 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1008381 [EM]<<< [E:14541r M:133783987] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1008392 IN Sending msg 133783987 on secure session with LSID: 23690 D: 1008399 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70) D: 1008407 [DMG]Command handler moving to [CommandSen] D: 1008412 [DMG]Command handler moving to [AwaitingDe] D: 1008417 [DL]Using Thread extended MAC for hostname. I: 1008422 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD I: 1008428 [SVR]Operational advertising enabled D: 1008475 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 1008718 [DL]SRP update succeeded I: 1008721 [DIS]Setting operational delegate post init I: 1008729 [SWU]Stopping the watchdog timer I: 1008733 [SWU]Starting the periodic query timer, timeout: 86400 seconds I: 1008740 [DIS]Updating services using commissioning mode 0 D: 1008745 [DL]Using Thread extended MAC for hostname. I: 1008750 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD I: 1008757 [DL]advertising srp service: B693EC17E2AE5718-00000000089EC2FD._matter._tcp D: 1008765 [DL]Using Thread extended MAC for hostname. I: 1008771 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 I: 1008780 [DL]advertising srp service: A4CA2DC385042010._matterc._udp D: 1008787 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2d731668 D: 1008794 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2d731669 D: 1009461 [DL]SRP update succeeded D: 1010995 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 1012514 [EM]>>> [E:14542r M:132793808] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1012525 [EM]Handling via exchange: 14542r, Delegate: 0x200050a0 I: 1012533 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1012541 [IN]CASE Server disabling CASE session setups I: 1012546 [EM]<<< [E:14542r M:260362354 (Ack:132793808)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1012559 IN Sending msg 260362354 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909' D: 1012570 [EM]Flushed pending ack for MessageCounter:132793808 on exchange 14542r I: 1012577 [SC]Received Sigma1 msg D: 1012581 [SC]Found MRP parameters in the message D: 1012586 [SC]Peer assigned session key ID 49620 I: 1012594 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x00000000089EC2FD D: 1012789 [SC]Including MRP parameters I: 1012793 [EM]<<< [E:14542r M:260362355 (Ack:132793808)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) I: 1012806 IN Sending msg 260362355 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909' I: 1012818 [SC]Sent Sigma2 msg I: 1012948 [EM]>>> [E:14542r M:132793809 (Ack:260362355)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1012961 [EM]Found matching exchange: 14542r, Delegate: 0x200050bc D: 1012968 [EM]Rxd Ack; Removing MessageCounter:260362355 from Retrans Table on exchange 14542r I: 1013048 [EM]>>> [E:14542r M:132793810 (Ack:260362355)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) D: 1013061 [EM]Found matching exchange: 14542r, Delegate: 0x200050bc D: 1013067 [EM]CHIP MessageCounter:260362355 not in RetransTable on exchange 14542r I: 1013074 [EM]<<< [E:14542r M:260362356 (Ack:132793810)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1013087 IN Sending msg 260362356 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909' D: 1013098 [EM]Flushed pending ack for MessageCounter:132793810 on exchange 14542r I: 1013106 [SC]Received Sigma3 msg E: 1013114 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time D: 1013298 [SC]Sending status report. Protocol code 0, exchange 14542 I: 1013304 [EM]<<< [E:14542r M:260362357 (Ack:132793810)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1013317 IN Sending msg 260362357 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909' I: 1013329 [SC]SecureSession[0x200044e8]: Moving from state 'kEstablishing' --> 'kActive' D: 1013337 [IN]SecureSession[0x200044e8]: Activated - Type:2 LSID:23689 D: 1013344 [IN]New secure session activated for device <000000009D6A13AE, 1>, LSID:23689 PSID:49620! I: 1013354 [IN]CASE Session established to peer: <000000009D6A13AE, 1> I: 1013360 [IN]CASE Server enabling CASE session setups D: 1013368 [IN]SecureSession[0x200045a0]: Allocated Type:2 LSID:23691 D: 1013377 [SC]Allocated SecureSession (0x200045a0) - waiting for Sigma1 msg I: 1013384 [EM]>>> [E:14542r M:132793811 (Ack:260362357)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1013397 [EM]Found matching exchange: 14542r, Delegate: (nil) D: 1013403 [EM]Rxd Ack; Removing MessageCounter:260362357 from Retrans Table on exchange 14542r I: 1013412 [EM]>>> [E:14543r M:138164629] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1013423 [EM]Handling via exchange: 14543r, Delegate: 0x20008ab4 D: 1013429 [IM]Received Read request D: 1013433 [DMG]IM RH moving to [GeneratingReports] D: 1013438 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1013446 [DMG] Cluster 3c, Attribute 0 is dirty D: 1013451 [DMG]Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D: 1013461 [DMG] Sending report (payload has 36 bytes)... I: 1013467 [EM]<<< [E:14543r M:5901398 (Ack:138164629)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1013479 IN Sending msg 5901398 on secure session with LSID: 23689 D: 1013487 [DMG] OnReportConfirm: NumReports = 0 D: 1013492 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1013500 [DMG]IM RH moving to [AwaitingDestruction] D: 1013505 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 1013511 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) I: 1013526 [EM]>>> [E:14543r M:138164630 (Ack:5901398)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1013539 [EM]Found matching exchange: 14543r, Delegate: (nil) D: 1013544 [EM]Rxd Ack; Removing MessageCounter:5901398 from Retrans Table on exchange 14543r D: 1013605 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) I: 1013818 [EM]>>> [E:14544r M:138164631] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1013829 [EM]Handling via exchange: 14544r, Delegate: 0x20008ab4 D: 1013834 [IM]Received Read request D: 1013838 [DMG]IM RH moving to [GeneratingReports] D: 1013843 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1013852 [DMG] Cluster 1d, Attribute 3 is dirty D: 1013857 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 1013866 [DMG] Sending report (payload has 64 bytes)... I: 1013873 [EM]<<< [E:14544r M:5901399 (Ack:138164631)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1013884 IN Sending msg 5901399 on secure session with LSID: 23689 D: 1013893 [DMG] OnReportConfirm: NumReports = 0 D: 1013897 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1013905 [DMG]IM RH moving to [AwaitingDestruction] D: 1013911 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1013944 [EM]>>> [E:14544r M:138164632 (Ack:5901399)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1013959 [EM]Found matching exchange: 14544r, Delegate: (nil) D: 1013965 [EM]Rxd Ack; Removing MessageCounter:5901399 from Retrans Table on exchange 14544r I: 1013975 [EM]>>> [E:14545r M:138164633] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1013985 [EM]Handling via exchange: 14545r, Delegate: 0x20008ab4 D: 1013991 [IM]Received Read request D: 1013995 [DMG]IM RH moving to [GeneratingReports] D: 1014000 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014008 [DMG] Cluster 1d, Attribute 0 is dirty D: 1014014 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D: 1014023 [DMG] Sending report (payload has 70 bytes)... I: 1014029 [EM]<<< [E:14545r M:5901400 (Ack:138164633)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014041 IN Sending msg 5901400 on secure session with LSID: 23689 D: 1014049 [DMG] OnReportConfirm: NumReports = 0 D: 1014054 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014061 [DMG]IM RH moving to [AwaitingDestruction] D: 1014067 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014102 [EM]>>> [E:14545r M:138164634 (Ack:5901400)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014117 [EM]Found matching exchange: 14545r, Delegate: (nil) D: 1014123 [EM]Rxd Ack; Removing MessageCounter:5901400 from Retrans Table on exchange 14545r I: 1014132 [EM]>>> [E:14546r M:138164635] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014142 [EM]Handling via exchange: 14546r, Delegate: 0x20008ab4 D: 1014148 [IM]Received Read request D: 1014152 [DMG]IM RH moving to [GeneratingReports] D: 1014157 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014166 [DMG] Cluster 1d, Attribute 1 is dirty D: 1014171 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 1014181 [DMG] Sending report (payload has 400 bytes)... I: 1014189 [EM]<<< [E:14546r M:5901401 (Ack:138164635)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014200 IN Sending msg 5901401 on secure session with LSID: 23689 D: 1014209 [DMG] OnReportConfirm: NumReports = 0 D: 1014213 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014221 [DMG]IM RH moving to [AwaitingDestruction] D: 1014226 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014288 [EM]>>> [E:14546r M:138164636 (Ack:5901401)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014304 [EM]Found matching exchange: 14546r, Delegate: (nil) D: 1014310 [EM]Rxd Ack; Removing MessageCounter:5901401 from Retrans Table on exchange 14546r I: 1014319 [EM]>>> [E:14547r M:138164637] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014329 [EM]Handling via exchange: 14547r, Delegate: 0x20008ab4 D: 1014335 [IM]Received Read request D: 1014339 [DMG]IM RH moving to [GeneratingReports] D: 1014344 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014353 [DMG] Cluster 1d, Attribute 2 is dirty D: 1014358 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 1014367 [DMG] Sending report (payload has 64 bytes)... I: 1014374 [EM]<<< [E:14547r M:5901402 (Ack:138164637)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014385 IN Sending msg 5901402 on secure session with LSID: 23689 D: 1014393 [DMG] OnReportConfirm: NumReports = 0 D: 1014398 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014406 [DMG]IM RH moving to [AwaitingDestruction] D: 1014411 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014449 [EM]>>> [E:14547r M:138164638 (Ack:5901402)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014465 [EM]Found matching exchange: 14547r, Delegate: (nil) D: 1014471 [EM]Rxd Ack; Removing MessageCounter:5901402 from Retrans Table on exchange 14547r I: 1014480 [EM]>>> [E:14548r M:138164639] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014490 [EM]Handling via exchange: 14548r, Delegate: 0x20008ab4 D: 1014496 [IM]Received Read request D: 1014500 [DMG]IM RH moving to [GeneratingReports] D: 1014505 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014514 [DMG] Cluster 1d, Attribute 3 is dirty D: 1014519 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0) D: 1014528 [DMG] Sending report (payload has 36 bytes)... I: 1014534 [EM]<<< [E:14548r M:5901403 (Ack:138164639)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014546 IN Sending msg 5901403 on secure session with LSID: 23689 D: 1014554 [DMG] OnReportConfirm: NumReports = 0 D: 1014559 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014567 [DMG]IM RH moving to [AwaitingDestruction] D: 1014572 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014582 [EM]>>> [E:14548r M:138164640 (Ack:5901403)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014598 [EM]Found matching exchange: 14548r, Delegate: (nil) D: 1014604 [EM]Rxd Ack; Removing MessageCounter:5901403 from Retrans Table on exchange 14548r I: 1014613 [EM]>>> [E:14549r M:138164641] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014623 [EM]Handling via exchange: 14549r, Delegate: 0x20008ab4 D: 1014629 [IM]Received Read request D: 1014633 [DMG]IM RH moving to [GeneratingReports] D: 1014638 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014647 [DMG] Cluster 1d, Attribute 0 is dirty D: 1014652 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0) D: 1014661 [DMG] Sending report (payload has 71 bytes)... I: 1014668 [EM]<<< [E:14549r M:5901404 (Ack:138164641)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014679 IN Sending msg 5901404 on secure session with LSID: 23689 D: 1014687 [DMG] OnReportConfirm: NumReports = 0 D: 1014692 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014700 [DMG]IM RH moving to [AwaitingDestruction] D: 1014705 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014740 [EM]>>> [E:14549r M:138164642 (Ack:5901404)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014755 [EM]Found matching exchange: 14549r, Delegate: (nil) D: 1014761 [EM]Rxd Ack; Removing MessageCounter:5901404 from Retrans Table on exchange 14549r I: 1014770 [EM]>>> [E:14550r M:138164643] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014781 [EM]Handling via exchange: 14550r, Delegate: 0x20008ab4 D: 1014787 [IM]Received Read request D: 1014791 [DMG]IM RH moving to [GeneratingReports] D: 1014796 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014804 [DMG] Cluster 1d, Attribute 1 is dirty D: 1014810 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0) D: 1014819 [DMG] Sending report (payload has 176 bytes)... I: 1014826 [EM]<<< [E:14550r M:5901405 (Ack:138164643)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1014837 IN Sending msg 5901405 on secure session with LSID: 23689 D: 1014846 [DMG] OnReportConfirm: NumReports = 0 D: 1014851 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1014858 [DMG]IM RH moving to [AwaitingDestruction] D: 1014864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1014905 [EM]>>> [E:14550r M:138164644 (Ack:5901405)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1014918 [EM]Found matching exchange: 14550r, Delegate: (nil) D: 1014926 [EM]Rxd Ack; Removing MessageCounter:5901405 from Retrans Table on exchange 14550r I: 1014936 [EM]>>> [E:14551r M:138164645] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest) D: 1014946 [EM]Handling via exchange: 14551r, Delegate: 0x20008ab4 D: 1014952 [IM]Received Read request D: 1014956 [DMG]IM RH moving to [GeneratingReports] D: 1014961 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 1014970 [DMG] Cluster 1d, Attribute 2 is dirty D: 1014975 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0002 (expanded=0) D: 1014984 [DMG] Sending report (payload has 36 bytes)... I: 1014990 [EM]<<< [E:14551r M:5901406 (Ack:138164645)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData) I: 1015002 IN Sending msg 5901406 on secure session with LSID: 23689 D: 1015010 [DMG] OnReportConfirm: NumReports = 0 D: 1015015 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 1015023 [DMG]IM RH moving to [AwaitingDestruction] D: 1015028 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet I: 1015039 [EM]>>> [E:14551r M:138164646 (Ack:5901406)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1015052 [EM]Found matching exchange: 14551r, Delegate: (nil) D: 1015058 [EM]Rxd Ack; Removing MessageCounter:5901406 from Retrans Table on exchange 14551r D: 1016080 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 1018587 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 1018645 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) I: 1019924 [EM]>>> [E:14552r M:138164647] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:08 (IM:InvokeCommandRequest) D: 1019935 [EM]Handling via exchange: 14552r, Delegate: 0x20008ab4 D: 1019941 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 I: 1019949 [FS]GeneralCommissioning: Received CommissioningComplete I: 1019958 [FP]Metadata for Fabric 0x1 persisted to storage. I: 1019981 [TS]Committing Last Known Good Time to storage: 2022-11-28T23:51:29 I: 1019991 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0xB693EC17E2AE5718, FabricId 1300E90F1AAADEC2, NodeId 00000000089EC2FD, VendorId 0x6006 I: 1020007 [FS]GeneralCommissioning: Successfully commited pending fabric data I: 1020014 [FS]Fail-safe cleanly disarmed D: 1020018 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685677 D: 1020025 [DMG]Command handler moving to [ Preparing] D: 1020030 [DMG]Command handler moving to [AddingComm] D: 1020035 [DMG]Command handler moving to [AddedComma] D: 1020040 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 1020047 [EM]<<< [E:14552r M:5901407 (Ack:138164647)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:09 (IM:InvokeCommandResponse) I: 1020059 IN Sending msg 5901407 on secure session with LSID: 23689 D: 1020068 [DMG]Command handler moving to [CommandSen] D: 1020073 [DMG]Command handler moving to [AwaitingDe] I: 1020078 [SWU]Device commissioned, schedule a default provider query I: 1020085 [SVR]Commissioning completed successfully I: 1020090 [DIS]Updating services using commissioning mode 0 D: 1020098 [DL]Using Thread extended MAC for hostname. I: 1020103 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD D: 1020110 [DL]Using Thread extended MAC for hostname. I: 1020116 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 D: 1020126 [IN]Expiring all PASE sessions D: 1020129 [IN]SecureSession[0x20004430]: MarkForEviction Type:1 LSID:23690 I: 1020136 [SC]SecureSession[0x20004430]: Moving from state 'kActive' --> 'kPendingEviction' D: 1020144 [IN]SecureSession[0x20004430]: Released - Type:1 LSID:23690 D: 1020151 [IN]Clearing BLE pending packets. I: 1020155 [BLE]Releasing end point's BLE connection back to application. I: 1020161 [DL]Closing BLE GATT connection (ConnId 00) D: 1020167 [ZCL]Commissioning complete, notify platform driver to persist network credentials. I: 1020177 [EM]>>> [E:14552r M:138164648 (Ack:5901407)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1020190 [EM]Found matching exchange: 14552r, Delegate: (nil) D: 1020196 [EM]Rxd Ack; Removing MessageCounter:5901407 from Retrans Table on exchange 14552r I: 1020220 [DL]BLE GAP connection terminated (reason 0x16) I: 1020225 [DL]Current number of connections: 0/2 I: 1031496 [EM]>>> [E:64039r M:56521657] (U) Msg RX from 0:6D9EABC7D5A23C65 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1031507 [EM]Handling via exchange: 64039r, Delegate: 0x200050a0 I: 1031513 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1031521 [IN]CASE Server disabling CASE session setups I: 1031526 [EM]<<< [E:64039r M:260362358 (Ack:56521657)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1031539 IN Sending msg 260362358 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1031549 [EM]Flushed pending ack for MessageCounter:56521657 on exchange 64039r I: 1031557 [SC]Received Sigma1 msg D: 1031561 [SC]Found MRP parameters in the message D: 1031566 [SC]Peer assigned session key ID 58287 E: 1031574 [SC]CASE failed to match destination ID with local fabrics D: 1031580 [SC]0x7e, 0x1b, 0x7e, 0x47, 0xc9, 0x5a, 0x1a, 0x2b, D: 1031586 [SC]0x4c, 0x69, 0xa3, 0x6e, 0x58, 0x0f, 0x4b, 0xbb, D: 1031592 [SC]0x53, 0xfe, 0x12, 0x73, 0x29, 0xce, 0x62, 0xe6, D: 1031598 [SC]0xe7, 0xbb, 0xbe, 0x46, 0x01, 0xb0, 0x19, 0x81, D: 1031603 [SC]Sending status report. Protocol code 2, exchange 64039 I: 1031610 [EM]<<< [E:64039r M:260362359 (Ack:56521657)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1031622 IN Sending msg 260362359 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1031633 [IN]CASE Session establishment failed: 71 I: 1031639 [IN]CASE Server enabling CASE session setups D: 1031644 [IN]SecureSession[0x200045a0]: Released - Type:2 LSID:23691 D: 1031654 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23692 D: 1031660 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1031667 [EM]OnMessageReceived failed, err = 71 I: 1031671 [IN]CASE Server enabling CASE session setups D: 1031676 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23692 D: 1031683 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23693 D: 1031689 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1031696 [EM]>>> [E:64039r M:56521658 (Ack:260362359)] (U) Msg RX from 0:6D9EABC7D5A23C65 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1031709 [EM]Found matching exchange: 64039r, Delegate: (nil) D: 1031715 [EM]Rxd Ack; Removing MessageCounter:260362359 from Retrans Table on exchange 64039r I: 1033871 [EM]>>> [E:64040r M:56521659] (U) Msg RX from 0:47147F085086D535 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1033882 [EM]Handling via exchange: 64040r, Delegate: 0x200050a0 I: 1033888 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1033896 [IN]CASE Server disabling CASE session setups I: 1033901 [EM]<<< [E:64040r M:260362360 (Ack:56521659)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1033914 IN Sending msg 260362360 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1033924 [EM]Flushed pending ack for MessageCounter:56521659 on exchange 64040r I: 1033932 [SC]Received Sigma1 msg D: 1033936 [SC]Found MRP parameters in the message D: 1033941 [SC]Peer assigned session key ID 58288 E: 1033949 [SC]CASE failed to match destination ID with local fabrics D: 1033955 [SC]0x20, 0x77, 0xd2, 0x94, 0x15, 0x96, 0x12, 0xb7, D: 1033961 [SC]0x80, 0xd2, 0xef, 0x75, 0xcc, 0xb9, 0x80, 0x2f, D: 1033967 [SC]0xd7, 0x10, 0x4c, 0x2b, 0x74, 0xdc, 0x52, 0xe7, D: 1033972 [SC]0xad, 0x69, 0x0f, 0x3a, 0xd6, 0xcc, 0xde, 0x88, D: 1033978 [SC]Sending status report. Protocol code 2, exchange 64040 I: 1033985 [EM]<<< [E:64040r M:260362361 (Ack:56521659)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1033997 IN Sending msg 260362361 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1034009 [IN]CASE Session establishment failed: 71 I: 1034014 [IN]CASE Server enabling CASE session setups D: 1034019 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23693 D: 1034028 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23694 D: 1034035 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1034041 [EM]OnMessageReceived failed, err = 71 I: 1034046 [IN]CASE Server enabling CASE session setups D: 1034051 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23694 D: 1034058 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23695 D: 1034064 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1034071 [EM]>>> [E:64040r M:56521660 (Ack:260362361)] (U) Msg RX from 0:47147F085086D535 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1034084 [EM]Found matching exchange: 64040r, Delegate: (nil) D: 1034090 [EM]Rxd Ack; Removing MessageCounter:260362361 from Retrans Table on exchange 64040r I: 1038255 [EM]>>> [E:64041r M:56521661] (U) Msg RX from 0:6C33328D7A37F9BC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1038266 [EM]Handling via exchange: 64041r, Delegate: 0x200050a0 I: 1038272 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1038280 [IN]CASE Server disabling CASE session setups I: 1038285 [EM]<<< [E:64041r M:260362362 (Ack:56521661)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1038298 IN Sending msg 260362362 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1038308 [EM]Flushed pending ack for MessageCounter:56521661 on exchange 64041r I: 1038316 [SC]Received Sigma1 msg D: 1038319 [SC]Found MRP parameters in the message D: 1038324 [SC]Peer assigned session key ID 58289 E: 1038333 [SC]CASE failed to match destination ID with local fabrics D: 1038339 [SC]0xf8, 0x0b, 0x28, 0x64, 0x3d, 0x80, 0xa2, 0xc4, D: 1038345 [SC]0x3a, 0xbf, 0x57, 0x4f, 0xac, 0x73, 0x60, 0xc1, D: 1038351 [SC]0x83, 0xdb, 0x3c, 0xc2, 0xe0, 0x00, 0xe6, 0xbb, D: 1038357 [SC]0xfc, 0x33, 0x34, 0x13, 0xef, 0xfb, 0x0c, 0x7a, D: 1038362 [SC]Sending status report. Protocol code 2, exchange 64041 I: 1038369 [EM]<<< [E:64041r M:260362363 (Ack:56521661)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1038382 IN Sending msg 260362363 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1038393 [IN]CASE Session establishment failed: 71 I: 1038397 [IN]CASE Server enabling CASE session setups D: 1038403 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23695 D: 1038413 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23696 D: 1038419 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1038426 [EM]OnMessageReceived failed, err = 71 I: 1038430 [IN]CASE Server enabling CASE session setups D: 1038435 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23696 D: 1038442 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23697 D: 1038448 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1038455 [EM]>>> [E:64041r M:56521662 (Ack:260362363)] (U) Msg RX from 0:6C33328D7A37F9BC [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1038468 [EM]Found matching exchange: 64041r, Delegate: (nil) D: 1038474 [EM]Rxd Ack; Removing MessageCounter:260362363 from Retrans Table on exchange 64041r I: 1046632 [EM]>>> [E:64042r M:56521663] (U) Msg RX from 0:FB15CEF7976D7F86 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1046644 [EM]Handling via exchange: 64042r, Delegate: 0x200050a0 I: 1046650 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1046657 [IN]CASE Server disabling CASE session setups I: 1046663 [EM]<<< [E:64042r M:260362364 (Ack:56521663)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1046675 IN Sending msg 260362364 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1046686 [EM]Flushed pending ack for MessageCounter:56521663 on exchange 64042r I: 1046694 [SC]Received Sigma1 msg D: 1046698 [SC]Found MRP parameters in the message D: 1046703 [SC]Peer assigned session key ID 58290 E: 1046710 [SC]CASE failed to match destination ID with local fabrics D: 1046717 [SC]0x68, 0x8c, 0x22, 0xf3, 0x9a, 0x56, 0x43, 0xe9, D: 1046723 [SC]0x87, 0x4d, 0x44, 0x70, 0x00, 0x11, 0xf1, 0x8c, D: 1046728 [SC]0x66, 0xf9, 0xaa, 0xc7, 0x83, 0x4e, 0xbd, 0x41, D: 1046734 [SC]0x95, 0x7b, 0xc5, 0xcc, 0x43, 0x89, 0x68, 0x0f, D: 1046740 [SC]Sending status report. Protocol code 2, exchange 64042 I: 1046746 [EM]<<< [E:64042r M:260362365 (Ack:56521663)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1046759 IN Sending msg 260362365 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1046770 [IN]CASE Session establishment failed: 71 I: 1046775 [IN]CASE Server enabling CASE session setups D: 1046781 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23697 D: 1046790 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23698 D: 1046797 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1046803 [EM]OnMessageReceived failed, err = 71 I: 1046808 [IN]CASE Server enabling CASE session setups D: 1046813 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23698 D: 1046820 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23699 D: 1046826 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1046833 [EM]>>> [E:64042r M:56521664 (Ack:260362365)] (U) Msg RX from 0:FB15CEF7976D7F86 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1046846 [EM]Found matching exchange: 64042r, Delegate: (nil) D: 1046852 [EM]Rxd Ack; Removing MessageCounter:260362365 from Retrans Table on exchange 64042r E: 1050085 [SWU]No suitable OTA Provider candidate found I: 1050090 [SWU]No provider available I: 1063021 [EM]>>> [E:64043r M:56521665] (U) Msg RX from 0:F7FC311E0205C58F [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1063032 [EM]Handling via exchange: 64043r, Delegate: 0x200050a0 I: 1063038 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1063045 [IN]CASE Server disabling CASE session setups I: 1063051 [EM]<<< [E:64043r M:260362366 (Ack:56521665)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1063064 IN Sending msg 260362366 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1063074 [EM]Flushed pending ack for MessageCounter:56521665 on exchange 64043r I: 1063081 [SC]Received Sigma1 msg D: 1063085 [SC]Found MRP parameters in the message D: 1063090 [SC]Peer assigned session key ID 58291 E: 1063099 [SC]CASE failed to match destination ID with local fabrics D: 1063105 [SC]0xff, 0x61, 0xaa, 0x4b, 0xa1, 0x05, 0x92, 0x03, D: 1063111 [SC]0xfa, 0xc0, 0x30, 0xe1, 0x55, 0xb6, 0xad, 0xec, D: 1063116 [SC]0xce, 0xa0, 0x51, 0xf5, 0xe4, 0xef, 0x98, 0x23, D: 1063122 [SC]0x22, 0x56, 0xc4, 0x65, 0xad, 0xfe, 0xb3, 0x9d, D: 1063128 [SC]Sending status report. Protocol code 2, exchange 64043 I: 1063134 [EM]<<< [E:64043r M:260362367 (Ack:56521665)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1063147 IN Sending msg 260362367 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1063158 [IN]CASE Session establishment failed: 71 I: 1063163 [IN]CASE Server enabling CASE session setups D: 1063169 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23699 D: 1063178 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23700 D: 1063184 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1063191 [EM]OnMessageReceived failed, err = 71 I: 1063196 [IN]CASE Server enabling CASE session setups D: 1063201 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23700 D: 1063207 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23701 D: 1063214 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1063221 [EM]>>> [E:64043r M:56521666 (Ack:260362367)] (U) Msg RX from 0:F7FC311E0205C58F [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1063234 [EM]Found matching exchange: 64043r, Delegate: (nil) D: 1063239 [EM]Rxd Ack; Removing MessageCounter:260362367 from Retrans Table on exchange 64043r D: 1067510 [DL]OpenThread State Changed (Flags: 0x00000064) D: 1067515 [DL] Device Role: ROUTER I: 1095434 [EM]>>> [E:64044r M:56521667] (U) Msg RX from 0:91FDAF209C3ABBF7 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) D: 1095445 [EM]Handling via exchange: 64044r, Delegate: 0x200050a0 I: 1095451 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0 I: 1095459 [IN]CASE Server disabling CASE session setups I: 1095464 [EM]<<< [E:64044r M:260362368 (Ack:56521667)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) I: 1095477 IN Sending msg 260362368 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' D: 1095488 [EM]Flushed pending ack for MessageCounter:56521667 on exchange 64044r I: 1095496 [SC]Received Sigma1 msg D: 1095500 [SC]Found MRP parameters in the message D: 1095505 [SC]Peer assigned session key ID 58292 E: 1095515 [SC]CASE failed to match destination ID with local fabrics D: 1095522 [SC]0x36, 0xfd, 0x1c, 0xef, 0x43, 0xa8, 0x92, 0xe2, D: 1095528 [SC]0x79, 0x16, 0x3b, 0x91, 0xbe, 0x78, 0x9a, 0x19, D: 1095534 [SC]0xeb, 0x67, 0x72, 0x74, 0x72, 0xbb, 0x76, 0x0b, D: 1095540 [SC]0x14, 0x17, 0xb4, 0x82, 0x09, 0xd0, 0x39, 0x65, D: 1095546 [SC]Sending status report. Protocol code 2, exchange 64044 I: 1095552 [EM]<<< [E:64044r M:260362369 (Ack:56521667)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 1095565 IN Sending msg 260362369 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540' E: 1095576 [IN]CASE Session establishment failed: 71 I: 1095581 [IN]CASE Server enabling CASE session setups D: 1095587 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23701 D: 1095596 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23702 D: 1095603 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg E: 1095609 [EM]OnMessageReceived failed, err = 71 I: 1095614 [IN]CASE Server enabling CASE session setups D: 1095619 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23702 D: 1095626 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23703 D: 1095632 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg I: 1095639 [EM]>>> [E:64044r M:56521668 (Ack:260362369)] (U) Msg RX from 0:91FDAF209C3ABBF7 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) D: 1095652 [EM]Found matching exchange: 64044r, Delegate: (nil) D: 1095658 [EM]Rxd Ack; Removing MessageCounter:260362369 from Retrans Table on exchange 64044r `

resghst commented 1 year ago

@FutronicsMP could you tell me how to update Nest Hub 2 to version 1.56.324896. Because my Nest Hub 2 version still stays on 1.56.309385.

rochaferraz commented 1 year ago

Hi @FutronicsMP, @benjaminnestler the cloud flag change is published, but it takes several days to take effect on the whole device population, sorry for the temporary down time.

@resghst the hub updates are automatic. The gradual rollout is also true for Nest Hub 2nd gen updates, but please note that only those specific devices of users enrolled in Matter Public Preview will be affected before launch.

FutronicsMP commented 1 year ago

@FutronicsMP could you tell me how to update Nest Hub 2 to version 1.56.324896. Because my Nest Hub 2 version still stays on 1.56.309385.

@resghst In Google Home App choose Nest Hub 2 and choose automatic updates. I also checked the testing update program (In English it might be named differently - I'm trying to translate what I see in Google Home App in polish)

rochaferraz commented 1 year ago

@FutronicsMP, @benjaminnestler the rollout should have reached 100%. Please try again the commissioning-control on your setups. Thanks!

FutronicsMP commented 1 year ago

@rochaferraz Thank you for the information, I will do some tests and let you know. So far I tested nRF 2.2.0 SDK with Apple Home pod mini and everything working perfectly fine :)

AlexeyYukhin commented 1 year ago

@FutronicsMP, @benjaminnestler the rollout should have reached 100%. Please try again the commissioning-control on your setups. Thanks!

hi. I also have Google Nest Hub Gen2 and switched development program (testing update program) ON. But it's still on 1.56.309385 chromecast firmware version (47.9.4.447810048 software version).

Is there anything wrong I'm doing?

benjaminnestler commented 1 year ago

@AlexeyYukhin I think we have to wait until the update reached our devices :-(

oblaser commented 1 year ago

So, now it works for me. Here's what I've done:

  1. setup a Matter Integration in the Google Developper Console (Light 0xFFF1 0x8005)
  2. enable software preview for GHA and Nest (setting is stored in the cloud and does not get lost on reinstallations or resets)
  3. wait for the software update, maybe a reboot helps (Nest 47.9.4.447810048 1.56.324896 / GHA 2.60.1.22)
  4. remove all Matter devices and Nest in GHA
  5. reinstall GHA
  6. factory reset Nest
  7. add Nest to GHA
  8. comission device (device stays offline for a couple of seconds)
  9. use the device

I don't know if every step is really needed, but it's doing the job.

[Edit]

My Matter device is a nRF52840DK with the light_bulb sample, using nRF Connect v2.1.2

It also works with jakubdybczak/esp32-arduino-matter 0.0.1-alpha.1

alfonsotames commented 1 year ago

@FutronicsMP, @benjaminnestler the rollout should have reached 100%. Please try again the commissioning-control on your setups. Thanks!

I've been waiting for 5 or 6 days for the preview update but my Nest 2 still shows firmware 1.56.309385 :(

I tried to factory reset and reboot the device several times and nothing.

I can provision a Matter device but will still appear offline. I'm using nRF 2.1.2.

Is there something else I need to do besides enrolling in the Preview Program for the Nest 2 to be updated to 1.56.32? I'm baffled.

Thanks,

at

alfonsotames commented 1 year ago

The upgrade 1.56.32 hit today before dawn and now it works without having to register the Matter Integration in the Google Developper Console.

benjaminnestler commented 1 year ago

Hi @alfonsotames, same behavior for me and my Google Nest Hub. The firmware update was received in the night. Now the Chromecast firmware version shows 1.56.324896 and my devices (Light bulb example on nrf5340DK and a custom thermostat based on nrf52840 dongle) are shown as online devices and the control of these devices works.

benjaminnestler commented 1 year ago

@FutronicsMP, I think we can close this issue ;-) It seems to be solved.

Ne01iu commented 1 year ago

The device still show offline in my environment, but work fine in the Apple Home app. Is there any suggestions?

Nest Hub 2 software version is: 47.9.4.447810048 Chromecast firmware version: 1.56.324896 Google Home App Versoin: 2.60.1.22 Nordic Light Example from SDK 2.1.2 Nordic 52840DK Board

BertLammers commented 1 year ago

For me it has worked for a few days after the Nest Hub 2 update to 1.56.324896. But after removing the Matter device and recommissioning it the problem is back. Commissioning works fine but the device is shown offline and cannot be controlled using the Google Home App or the Nest Hub. Controlling it via an iPhone and Homepod works without problems and I am also able to control it using the google sample app for matter (https://github.com/google-home/sample-app-for-matter-android).

alfonsotames commented 1 year ago

Try rebooting your devices. I also have encountered strange behavior when removing and adding devices again. They appear offline but after some reboots and waiting they appear again online.

I'm using nrf 2.1.2 and nest 2nd gen on preview 1.56.324896.

all the best,

at

On Fri, Dec 9, 2022 at 4:31 AM Bert @.***> wrote:

For me it has worked for a few days after the Nest Hub 2 update to 1.56.324896. But after removing the Matter device and recommissioning it the problem is back. Commissioning works fine but the device is shown offline and cannot be controlled using the Google Home App or the Nest Hub. Controlling it via an iPhone and Homepod works without problems and I am also able to control it using the google sample app for matter ( https://github.com/google-home/sample-app-for-matter-android).

— Reply to this email directly, view it on GitHub https://github.com/project-chip/connectedhomeip/issues/23761#issuecomment-1344130573, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAK75QXBDFEFMF64C2RG2ULWMMDAFANCNFSM6AAAAAASLI256A . You are receiving this because you were mentioned.Message ID: @.***>

cw-20021349 commented 1 year ago

hi

After Google Nest hub 2th generation new firmware release on 12/13, Nethub 2th firmware was updated. (https://support.google.com/googlenest/answer/7365257?hl=en#zippy=%2Ccurrent-preview-program-firmware-version)

And I checked the release notes on 12/15 and configured the environment for the Matter 1.0 test. (https://developers.home.google.com/matter/release-notes)

But it doesn't pair with the thread module. My thread module is a Light bulb sample model. Prior to the Matter 1.0 update, it paired normally.

Issue step

1-1 Thread module Power on (nordic nrf52840 <- Supports Matter 1.0 (use to sdk 2.2.0) 1-2 Enter Google Home (Nest hub 2th registered) 1-3 add and manage 1-4 Set up devcie 1-5 New device 1-6 found matter device 1-7 Scan Matter QR code 1-8 Connecting device to google home.. 1-9 pairing failed

The above issue is 100% reproducible.

My Developer Console https://drive.google.com/file/d/1njXeuUD9bBvl7k8SI6NhQSHJsPNH9H4z/view?usp=sharing

reproduce video https://drive.google.com/file/d/1TRbETcwY6YJobEYTo2NUoVxXFOSL9_ca/view?usp=sharing

Google Nest hub 2th fw version https://drive.google.com/file/d/1YNPXQSOzReG6HJFs2ZRZV0O943MyQVhk/view?usp=sharing

issue log https://drive.google.com/file/d/1sX0YCvFKEOkW_n-Tl7-wImFNqq0gTxwF/view?usp=share_link

Please advise on this matter.

dhrishi commented 1 year ago

@cw-20021349 I checked the phone app logs you've shared. This is a known regression from Google side in their latest update. We have already reported it to them. I will post when there is a fix available.

cw-20021349 commented 1 year ago

@dhrishi

https://www.googlenestcommunity.com/t5/Smart-Home-Developer-Forum/No-pairing-after-Google-Nest-2th-Matter-1-0-update/td-p/315260

According to the community's answer above, there are multiple projects in the Google Developer Console? is said to occur.

I actually tested by deleting all the projects and recreating just one project, but it still doesn't pair.

Do you think the project issues in the developer console are correct?

dhrishi commented 1 year ago

@cw-20021349 The issue has been fixed now. We can get the commissioning using Google Home functional

cw-20021349 commented 1 year ago

@dhrishi hi Commissioning was successful last Friday. thank you

alfonsotames commented 1 year ago

Is it me or it's again broken?

FHFS commented 1 year ago

Is it me or it's again broken?

I have had a similar problem. I was using the default ProductID(0xfff1) and VendorID(0x8005) for my nRF52840 device. I had a different vendorid(0xfff4) and productid(0xBEEF) on DeveloperConsole

I was unable to commission my device after removing it.

After I added the correct productid and vendorid to the developerconsole I was able to add my devices again.

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

stale[bot] commented 11 months ago

This stale issue has been automatically closed. Thank you for your contributions.