Since end of last year we experience severe problems when commissioning devices via Matter, using the Google Nest Hub. These problems are not happening when using an Apple Home Pod or a RaspberryPi based OTBR, so I think this is an exclusive Google problem.
The problem happens with both our own product as well as the Nordic Matter examples.
Nest Hub Versions:
- Software-Version: 47.9.4.447810048
- Chromecast-Version: 1.6.324896
In the Google Developer Console, we now have only one Matter project left. The device uses the test VID 0xFFF1 and PID 0x8004.
See the log using an nRF5340 DK and the lock-app log below
uart:~$ I: nRF5 802154 radio initialized I: 4 Sectors of 4096 bytes I: alloc wra: 0, f38 I: data wra: 0, ac *** Booting Zephyr OS build v3.2.99-ncs1 *** I: Init CHIP stack I: 167 [DL]BLE address: C7:1B:C3:F3:60:61 I: 188 [DL]OpenThread SED interval set to 1000ms I: 194 [DL]OpenThread started: OK I: 197 [DL]Setting OpenThread device type to SLEEPY END DEVICE I: 203 [SVR]Server initializing... D: 206 [FP]Initializing FabricTable from persistent storage I: 211 [TS]Last Known Good Time: 2023-01-04T09:27:58 I: 216 [DMG]AccessControl: initializing I: 220 [DMG]Examples::AccessControlDelegate::Init I: 224 [DMG]AccessControl: setting I: 227 [DMG]DefaultAclStorage: initializing I: 231 [DMG]DefaultAclStorage: 0 entries loaded D: 236 [IN]UDP::Init bind&listen port=5540 E: 240 [IN]SO_REUSEPORT failed: 109 D: 243 [IN]UDP::Init bound to port=5540 D: 246 [IN]BLEBase::Init - setting/overriding transport D: 251 [IN]TransportMgr initialized D: 256 [DL]Using Thread extended MAC for hostname. I: 262 [ZCL]Using ZAP configuration... D: 266 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 D: 273 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0 D: 280 [DMG]Failed to read stored attribute (0, 0x0000_002B, 0x0000_0000: a0 D: 287 [DMG]Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0 D: 294 [DMG]Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: a0 I: 303 [DMG]AccessControlCluster: initializing D: 307 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 59dcc41c D: 313 [DL]Boot reason: 6 D: 316 [ZCL]GeneralDiagnostics: OnDeviceReboot D: 320 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 379c3c6a D: 326 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000146 I: 340 [ZCL]Initiating Admin Commissioning cluster. I: 345 [ZCL]Door Lock server initialized E: 348 [ZCL]DeviceInfoProvider is not registered E: 353 [ZCL]Trying to write invalid Calendar Type E: 357 [ZCL]Failed to write calendar type with error: 0x87 I: 362 [ZCL]Door Lock cluster initialized at endpoint #1 D: 368 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf82627 D: 374 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf82628 D: 381 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf82629 D: 387 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262a D: 393 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262b D: 400 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262c D: 406 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262d D: 412 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262e I: 419 [DIS]Updating services using commissioning mode 0 D: 424 [DL]Using Thread extended MAC for hostname. D: 429 [DL]Using Thread extended MAC for hostname. I: 433 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3851/15 cm=0 E: 442 [DIS]Failed to advertise extended commissionable node: 3 D: 448 [DIS]Scheduling extended discovery timeout in 900s E: 453 [DIS]Failed to finalize service update: 1c I: 458 [DIS]Delaying proxy of operational discovery: missing delegate I: 464 [IN]CASE Server enabling CASE session setups D: 469 [IN]SecureSession[0x200040a8]: Allocated Type:2 LSID:62755 D: 475 [SC]Allocated SecureSession (0x200040a8) - waiting for Sigma1 msg I: 481 [SVR]Joining Multicast groups D: 484 [ZCL]Emitting StartUp event D: 488 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001E8 I: 502 [SVR]Server Listening... I: 505 [DL]Device Configuration: I: 508 [DL] Serial Number: 11223344556677889900 I: 512 [DL] Vendor Id: 65521 (0xFFF1) I: 515 [DL] Product Id: 32772 (0x8004) I: 519 [DL] Hardware Version: 0 I: 522 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 528 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3851 (0xF0B) I: 534 [DL] Manufacturing Date: (not set) I: 538 [DL] Device Type: 65535 (0xFFFF) I: 542 [SVR]SetupQRCode: [MT:4CT91S0.03LA0648G00] I: 547 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 553 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A4CT91S0.03LA0648G00 I: 562 [SVR]Manual pairing code: [34970112332] D: 566 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf8262f I: 573 [DL]CHIP task running I: 576 [DIS]Updating services using commissioning mode 0 D: 581 [DL]Using Thread extended MAC for hostname. D: 586 [DL]Using Thread extended MAC for hostname. I: 591 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3851/15 cm=0 E: 600 [DIS]Failed to advertise extended commissionable node: 3 E: 606 [DIS]Failed to finalize service update: 1c D: 611 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 5cf82630 D: 16597 [IN]SecureSession[0x20004160]: Allocated Type:1 LSID:62756 D: 16603 [SC]Assigned local session key ID 62756 D: 16608 [SC]Waiting for PBKDF param request D: 16612 [DL]CHIPoBLE advertising set to on I: 16616 [DIS]Updating services using commissioning mode 1 D: 16621 [DL]Using Thread extended MAC for hostname. D: 16626 [DL]Using Thread extended MAC for hostname. I: 16631 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3851/15 cm=1 E: 16640 [DIS]Failed to advertise commissionable node: 3 E: 16645 [DIS]Failed to finalize service update: 1c I: 16654 [DL]CHIPoBLE advertising started I: 16658 [DL]NFC Tag emulation started I: 33150 [DL]BLE connection established (ConnId: 0x00) I: 33155 [DL]Current number of connections: 1/2 I: 33160 [DL]CHIPoBLE advertising stopped I: 33164 [DL]NFC Tag emulation stopped D: 34003 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 34010 [BLE]local and remote recv window sizes = 5 I: 34015 [BLE]selected BTP version 4 I: 34019 [BLE]using BTP fragment sizes rx 128 / tx 128. D: 34024 [DL]ConnId: 0x00, New CCCD value: 0x0002 D: 34029 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 34036 [IN]BLE EndPoint 0x20010a30 Connection Complete I: 34041 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131) D: 34153 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34288 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 34295 [EM]>>> [E:48452r M:98574959] (U) Msg RX from 0:D36486F49E8D1639 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) D: 34307 [EM]Handling via exchange: 48452r, Delegate: 0x2000628c D: 34313 [SC]Received PBKDF param request D: 34317 [SC]Peer assigned session ID 46886 D: 34321 [SC]Found MRP parameters in the message D: 34325 [SC]Including MRP parameters in PBKDF param response I: 34331 [EM]<<< [E:48452r M:179227613] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 34343 [IN](U) Sending msg 179227613 to IP address 'BLE' D: 34348 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 34356 [SC]Sent PBKDF param response D: 34423 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34431 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14) D: 34513 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 34521 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 34528 [EM]>>> [E:48452r M:98574960] (U) Msg RX from 0:D36486F49E8D1639 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) D: 34539 [EM]Found matching exchange: 48452r, Delegate: 0x2000628c D: 34545 [SC]Received spake2p msg1 I: 36104 [EM]<<< [E:48452r M:179227614] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 36115 [IN](U) Sending msg 179227614 to IP address 'BLE' D: 36120 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 36128 [SC]Sent spake2p msg2 E: 36130 [DL]Long dispatch time: 1609 ms, for event type 16388 D: 36178 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36186 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) D: 36268 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36276 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36284 [EM]>>> [E:48452r M:98574961] (U) Msg RX from 0:D36486F49E8D1639 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) D: 36295 [EM]Found matching exchange: 48452r, Delegate: 0x2000628c D: 36300 [SC]Received spake2p msg3 D: 36304 [SC]Sending status report. Protocol code 0, exchange 48452 I: 36310 [EM]<<< [E:48452r M:179227615] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 36321 [IN](U) Sending msg 179227615 to IP address 'BLE' D: 36327 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) I: 36335 [SC]SecureSession[0x20004160]: Moving from state 'kEstablishing' --> 'kActive' D: 36343 [IN]SecureSession[0x20004160]: Activated - Type:1 LSID:62756 D: 36349 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:62756 PSID:46886! I: 36358 [SVR]Commissioning completed session establishment step I: 36364 [DIS]Updating services using commissioning mode 0 D: 36369 [DL]Using Thread extended MAC for hostname. D: 36374 [DL]Using Thread extended MAC for hostname. I: 36380 [DIS]Advertise commission parameter vendorID=65521 productID=32772 discriminator=3851/15 cm=0 E: 36389 [DIS]Failed to advertise extended commissionable node: 3 D: 36395 [DIS]Scheduling extended discovery timeout in 900s E: 36400 [DIS]Failed to finalize service update: 1c D: 36405 [DL]CHIPoBLE advertising set to off I: 36409 [SVR]Device completed Rendezvous process E: 36414 [DL]Long dispatch time: 138 ms, for event type 16388 D: 36419 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36427 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36435 [EM]>>> [E:48453r M:24250583] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 36445 [EM]Handling via exchange: 48453r, Delegate: 0x2000e3fc D: 36451 [IM]Received Read request D: 36455 [DMG]IM RH moving to [GeneratingReports] D: 36459 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 36468 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty D: 36473 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 36482 [DMG]<RE> Sending report (payload has 37 bytes)... I: 36488 [EM]<<< [E:48453r M:59387197] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 36498 [IN](S) Sending msg 59387197 on secure session with LSID: 62756 D: 36505 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 36512 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 36517 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 36524 [DMG]IM RH moving to [AwaitingDestruction] D: 36529 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 36583 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36591 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36599 [EM]>>> [E:48454r M:24250584] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 36609 [EM]Handling via exchange: 48454r, Delegate: 0x2000e3fc D: 36615 [IM]Received Read request D: 36619 [DMG]IM RH moving to [GeneratingReports] D: 36623 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 36632 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty D: 36637 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D: 36646 [DMG]<RE> Sending report (payload has 37 bytes)... I: 36652 [EM]<<< [E:48454r M:59387198] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 36662 [IN](S) Sending msg 59387198 on secure session with LSID: 62756 D: 36668 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 36676 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 36680 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 36688 [DMG]IM RH moving to [AwaitingDestruction] D: 36692 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 36763 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36771 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36779 [EM]>>> [E:48455r M:24250585] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 36789 [EM]Handling via exchange: 48455r, Delegate: 0x2000e3fc D: 36795 [IM]Received Read request D: 36799 [DMG]IM RH moving to [GeneratingReports] D: 36803 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 36812 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty D: 36817 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D: 36826 [DMG]<RE> Sending report (payload has 36 bytes)... I: 36832 [EM]<<< [E:48455r M:59387199] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 36842 [IN](S) Sending msg 59387199 on secure session with LSID: 62756 D: 36848 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 36856 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 36861 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 36868 [DMG]IM RH moving to [AwaitingDestruction] D: 36872 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 36943 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 36951 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 36959 [EM]>>> [E:48456r M:24250586] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 36969 [EM]Handling via exchange: 48456r, Delegate: 0x2000e3fc D: 36975 [IM]Received Read request D: 36979 [DMG]IM RH moving to [GeneratingReports] D: 36983 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 36992 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty D: 36997 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 37006 [DMG]<RE> Sending report (payload has 36 bytes)... I: 37012 [EM]<<< [E:48456r M:59387200] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 37022 [IN](S) Sending msg 59387200 on secure session with LSID: 62756 D: 37028 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 37036 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 37041 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 37048 [DMG]IM RH moving to [AwaitingDestruction] D: 37053 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 37123 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37131 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 37139 [EM]>>> [E:48457r M:24250587] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 37149 [EM]Handling via exchange: 48457r, Delegate: 0x2000e3fc D: 37155 [IM]Received Read request D: 37159 [DMG]IM RH moving to [GeneratingReports] D: 37163 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 37172 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty D: 37177 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 37186 [DMG]<RE> Sending report (payload has 36 bytes)... I: 37192 [EM]<<< [E:48457r M:59387201] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 37202 [IN](S) Sending msg 59387201 on secure session with LSID: 62756 D: 37208 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 37216 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 37221 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 37228 [DMG]IM RH moving to [AwaitingDestruction] D: 37232 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 37303 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37311 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 37319 [EM]>>> [E:48458r M:24250588] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 37329 [EM]Handling via exchange: 48458r, Delegate: 0x2000e3fc D: 37335 [IM]Received Read request D: 37339 [DMG]IM RH moving to [GeneratingReports] D: 37343 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 37352 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty D: 37357 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D: 37366 [DMG]<RE> Sending report (payload has 624 bytes)... I: 37375 [EM]<<< [E:48458r M:59387202] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 37385 [IN](S) Sending msg 59387202 on secure session with LSID: 62756 D: 37392 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37400 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 37404 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 37411 [DMG]IM RH moving to [AwaitingDestruction] D: 37416 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 37483 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37491 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37573 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37581 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37663 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37671 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37754 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37761 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 37769 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 37933 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 37941 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 30) D: 38023 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 38031 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 38039 [EM]>>> [E:48459r M:24250589] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 38049 [EM]Handling via exchange: 48459r, Delegate: 0x2000e3fc D: 38055 [IM]Received Read request D: 38059 [DMG]IM RH moving to [GeneratingReports] D: 38063 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 38072 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty D: 38077 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0) D: 38086 [DMG]<RE> Sending report (payload has 37 bytes)... I: 38092 [EM]<<< [E:48459r M:59387203] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 38102 [IN](S) Sending msg 59387203 on secure session with LSID: 62756 D: 38109 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72) D: 38116 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 38121 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 38128 [DMG]IM RH moving to [AwaitingDestruction] D: 38133 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 38248 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 39463 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 39471 [EM]>>> [E:48460r M:24250590] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 39481 [EM]Handling via exchange: 48460r, Delegate: 0x2000e3fc D: 39487 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f8 exchange 48460r I: 39495 [EM]<<< [E:48460r M:59387204] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 39506 [IN](S) Sending msg 59387204 on secure session with LSID: 62756 D: 39512 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 39520 [DMG]Timed Request time limit 0x000000000000C170: handler 0x2000e7f8 exchange 48460r D: 39598 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 39606 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 39614 [EM]>>> [E:48460r M:24250591] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 39625 [EM]Found matching exchange: 48460r, Delegate: 0x2000e7f8 D: 39631 [DMG]Timed following action arrived at 0x0000000000009ACF: handler 0x2000e7f8 exchange 48460r D: 39640 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f8 exchange 48460r D: 39648 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 I: 39656 [FS]GeneralCommissioning: Received ArmFailSafe (120s) D: 39661 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 59dcc41d D: 39668 [DMG]Command handler moving to [ Preparing] D: 39672 [DMG]Command handler moving to [AddingComm] D: 39677 [DMG]Command handler moving to [AddedComma] D: 39682 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 39689 [EM]<<< [E:48460r M:59387205] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 39700 [IN](S) Sending msg 59387205 on secure session with LSID: 62756 D: 39707 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 39714 [DMG]Command handler moving to [CommandSen] D: 39719 [DMG]Command handler moving to [AwaitingDe] E: 39724 [DL]Long dispatch time: 118 ms, for event type 16388 D: 39778 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 39786 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 39794 [EM]>>> [E:48461r M:24250592] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 39804 [EM]Handling via exchange: 48461r, Delegate: 0x2000e3fc D: 39810 [IM]Received Read request D: 39814 [DMG]IM RH moving to [GeneratingReports] D: 39818 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D: 39827 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty D: 39832 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D: 39841 [DMG]<RE> Sending report (payload has 36 bytes)... I: 39847 [EM]<<< [E:48461r M:59387206] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 39857 [IN](S) Sending msg 59387206 on secure session with LSID: 62756 D: 39863 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 39871 [DMG]<RE> OnReportConfirm: NumReports = 0 D: 39876 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages D: 39883 [DMG]IM RH moving to [AwaitingDestruction] D: 39888 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet D: 39958 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 39966 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 39974 [EM]>>> [E:48462r M:24250593] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest) D: 39984 [EM]Handling via exchange: 48462r, Delegate: 0x2000e3fc D: 39990 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f8 exchange 48462r I: 39998 [EM]<<< [E:48462r M:59387207] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse) I: 40009 [IN](S) Sending msg 59387207 on secure session with LSID: 62756 D: 40015 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43) D: 40023 [DMG]Timed Request time limit 0x000000000000C367: handler 0x2000e7f8 exchange 48462r D: 40093 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40101 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40109 [EM]>>> [E:48462r M:24250594] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 40120 [EM]Found matching exchange: 48462r, Delegate: 0x2000e7f8 D: 40126 [DMG]Timed following action arrived at 0x0000000000009CBE: handler 0x2000e7f8 exchange 48462r D: 40135 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f8 exchange 48462r D: 40143 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 40153 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 59dcc41e D: 40159 [DMG]Command handler moving to [ Preparing] D: 40164 [DMG]Command handler moving to [AddingComm] D: 40169 [DMG]Command handler moving to [AddedComma] D: 40174 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 40181 [EM]<<< [E:48462r M:59387208] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40192 [IN](S) Sending msg 59387208 on secure session with LSID: 62756 D: 40198 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) D: 40206 [DMG]Command handler moving to [CommandSen] D: 40211 [DMG]Command handler moving to [AwaitingDe] E: 40215 [DL]Long dispatch time: 114 ms, for event type 16388 D: 40273 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40281 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40289 [EM]>>> [E:48463r M:24250595] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 40300 [EM]Handling via exchange: 48463r, Delegate: 0x2000e3fc D: 40306 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 40314 [ZCL]OpCreds: Certificate Chain request received for DAC D: 40320 [DMG]Command handler moving to [ Preparing] D: 40324 [DMG]Command handler moving to [AddingComm] D: 40329 [DMG]Command handler moving to [AddedComma] D: 40334 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 40344 [EM]<<< [E:48463r M:59387209] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40354 [IN](S) Sending msg 59387209 on secure session with LSID: 62756 D: 40361 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40369 [DMG]Command handler moving to [CommandSen] D: 40373 [DMG]Command handler moving to [AwaitingDe] D: 40453 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40461 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40543 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40551 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40633 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40641 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40724 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40732 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 40739 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 58) D: 40813 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 40821 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 40829 [EM]>>> [E:48464r M:24250596] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 40840 [EM]Handling via exchange: 48464r, Delegate: 0x2000e3fc D: 40846 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 40854 [ZCL]OpCreds: Certificate Chain request received for PAI D: 40860 [DMG]Command handler moving to [ Preparing] D: 40864 [DMG]Command handler moving to [AddingComm] D: 40869 [DMG]Command handler moving to [AddedComma] D: 40874 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 40883 [EM]<<< [E:48464r M:59387210] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 40894 [IN](S) Sending msg 59387210 on secure session with LSID: 62756 D: 40901 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 40909 [DMG]Command handler moving to [CommandSen] D: 40913 [DMG]Command handler moving to [AwaitingDe] D: 40993 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41001 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41083 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41091 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41173 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41181 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41264 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41271 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 41279 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28) D: 41353 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41361 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 41369 [EM]>>> [E:48465r M:24250597] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 41380 [EM]Handling via exchange: 48465r, Delegate: 0x2000e3fc D: 41386 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 41394 [ZCL]OpCreds: Received an AttestationRequest command I: 41429 [ZCL]OpCreds: AttestationRequest successful. D: 41434 [DMG]Command handler moving to [ Preparing] D: 41438 [DMG]Command handler moving to [AddingComm] D: 41443 [DMG]Command handler moving to [AddedComma] D: 41448 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 41459 [EM]<<< [E:48465r M:59387211] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 41469 [IN](S) Sending msg 59387211 on secure session with LSID: 62756 D: 41476 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41484 [DMG]Command handler moving to [CommandSen] D: 41488 [DMG]Command handler moving to [AwaitingDe] E: 41493 [DL]Long dispatch time: 132 ms, for event type 16388 D: 41533 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41541 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41623 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41631 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41713 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41721 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41804 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41811 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) D: 41819 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 41893 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41901 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90) D: 41983 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 41991 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 41999 [EM]>>> [E:48466r M:24250598] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) D: 42010 [EM]Handling via exchange: 48466r, Delegate: 0x2000e3fc D: 42016 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 42024 [ZCL]OpCreds: Received a CSRRequest command D: 42029 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0 I: 42193 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 42227 [ZCL]OpCreds: CSRRequest successful. D: 42231 [DMG]Command handler moving to [ Preparing] D: 42236 [DMG]Command handler moving to [AddingComm] D: 42241 [DMG]Command handler moving to [AddedComma] D: 42246 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 42255 [EM]<<< [E:48466r M:59387212] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 42265 [IN](S) Sending msg 59387212 on secure session with LSID: 62756 D: 42272 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 42280 [DMG]Command handler moving to [CommandSen] D: 42284 [DMG]Command handler moving to [AwaitingDe] E: 42289 [DL]Long dispatch time: 298 ms, for event type 16388 D: 42343 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 42351 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 42433 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 42441 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128) D: 42523 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 42531 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3) D: 42614 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) D: 42621 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) I: 44278 [DL]BLE GAP connection terminated (reason 0x13) D: 44283 [IN]Clearing BLE pending packets. I: 44287 [DL]Current number of connections: 0/2
