[MATTER] Commissioning failed at Google home

[Jeffery]

Hi Nordic team

- ncs 2.2.0 light bulb/light switch/door lock/window covering samples at application core. 

  multiprotocol_rpmsg at network core.

- NRF52840 DK and NRF5340 DK

- Google Net hub 2 ()

- WiFi AP

- Latest Google home apps (2.63.1.12)  at smartphone (Samsung A52s, Android 13)

No matter which DK and which sample, commissioning always failed. Below was log information.

Fullscreen 7268.log.txt Download

I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 235726 [TS]Pending Last Known Good Time: 2023-01-09T13:39:51
I: 235732 [TS]Previous Last Known Good Time: 2023-01-09T13:39:51
I: 235737 [TS]Reverted Last Known Good Time to previous value
D: 235743 [ZCL]Emitting ShutDown event
D: 235747 [EVL]LogEvent event number: 0x0000000000000002 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x1 Sys timestamp: 0x00000000000398E2
D: 235761 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 235766 [DL]Performing factory reset
I: 235777 [DL]Erasing Thread persistent info...


uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, ab0
I: data wra: 0, 304
*** Booting Zephyr OS build v3.2.99-ncs1 ***
I: Init CHIP stack
I: 168 [DL]BLE address: D4:08:53:4D:E3:C4
I: 191 [DL]OpenThread started: OK
I: 194 [DL]Setting OpenThread device type to ROUTER
I: 198 [SVR]Server initializing...
D: 202 [FP]Initializing FabricTable from persistent storage
I: 207 [TS]Last Known Good Time: [unknown]
I: 211 [TS]Setting Last Known Good Time to firmware build time 2023-01-09T13:39:51
I: 219 [DMG]AccessControl: initializing
I: 223 [DMG]Examples::AccessControlDelegate::Init
I: 227 [DMG]AccessControl: setting
I: 230 [DMG]DefaultAclStorage: initializing
I: 234 [DMG]DefaultAclStorage: 0 entries loaded
D: 238 [IN]UDP::Init bind&listen port=5540
E: 242 [IN]SO_REUSEPORT failed: 109
D: 246 [IN]UDP::Init bound to port=5540
D: 249 [IN]BLEBase::Init - setting/overriding transport
D: 254 [IN]TransportMgr initialized
D: 260 [DL]Using Thread extended MAC for hostname.
I: 266 [ZCL]Using ZAP configuration...
D: 270 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 278 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: a0
D: 285 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 292 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: a0
D: 299 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 306 [DMG]AccessControlCluster: initializing
D: 310 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f46f1c39
D: 316 [DL]Boot reason: 6
D: 319 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 323 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 837c9987
D: 330 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000149
I: 343 [ZCL]Initiating Admin Commissioning cluster.
D: 348 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 4219a493
D: 354 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to db367b43
D: 361 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to db367b44
I: 367 [ZCL]On/Off set value: 1 0
I: 370 [ZCL]On/off already set to new value
D: 375 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 6edd45fa
I: 381 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 387 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 396 [IN]SecureSession[0x20004450]: Allocated Type:1 LSID:62705
D: 402 [SC]Assigned local session key ID 62705
D: 406 [SC]Waiting for PBKDF param request
D: 410 [DL]CHIPoBLE advertising set to on
I: 414 [DIS]Updating services using commissioning mode 1
D: 419 [DL]Using Thread extended MAC for hostname.
D: 424 [DL]Using Thread extended MAC for hostname.
I: 429 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 438 [DIS]Failed to advertise commissionable node: 3
E: 442 [DIS]Failed to finalize service update: 1c
I: 447 [DIS]Updating services using commissioning mode 1
D: 452 [DL]Using Thread extended MAC for hostname.
D: 457 [DL]Using Thread extended MAC for hostname.
I: 462 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 471 [DIS]Failed to advertise commissionable node: 3
E: 476 [DIS]Failed to finalize service update: 1c
I: 480 [DIS]Delaying proxy of operational discovery: missing delegate
I: 486 [IN]CASE Server enabling CASE session setups
D: 491 [IN]SecureSession[0x20004508]: Allocated Type:2 LSID:62706
D: 497 [SC]Allocated SecureSession (0x20004508) - waiting for Sigma1 msg
I: 503 [SVR]Joining Multicast groups
D: 507 [ZCL]Emitting StartUp event
D: 510 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001FE
I: 524 [SVR]Server Listening...
I: 527 [DL]Device Configuration:
I: 530 [DL]  Serial Number: 11223344556677889900
I: 534 [DL]  Vendor Id: 65521 (0xFFF1)
I: 538 [DL]  Product Id: 32773 (0x8005)
I: 541 [DL]  Hardware Version: 0
I: 545 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 550 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 557 [DL]  Manufacturing Date: (not set)
I: 561 [DL]  Device Type: 65535 (0xFFFF)
I: 565 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 569 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 575 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 584 [SVR]Manual pairing code: [34970112332]
I: 589 [DL]CHIP task running
I: 596 [DL]CHIPoBLE advertising started
D: 600 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 6d9d0caf
I: 607 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 612 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 6edd45fb
I: 618 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 624 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 632 [DL]NFC Tag emulation started
I: 30599 [DL]CHIPoBLE advertising mode changed to slow
I: 139286 [DL]BLE connection established (ConnId: 0x00)
I: 139292 [DL]Current number of connections: 1/2
I: 139296 [DL]CHIPoBLE advertising stopped
I: 139300 [DL]NFC Tag emulation stopped
D: 139743 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 139750 [BLE]local and remote recv window sizes = 5
I: 139755 [BLE]selected BTP version 4
I: 139758 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 139863 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 139867 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 139875 [IN]BLE EndPoint 0x20012d78 Connection Complete
I: 139880 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 139922 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 139931 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 139938 [EM]>>> [E:15520r M:54056484] (U) Msg RX from 0:C507A80039312A2A [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 139950 [EM]Handling via exchange: 15520r, Delegate: 0x20006634
D: 139955 [SC]Received PBKDF param request
D: 139959 [SC]Peer assigned session ID 62938
D: 139963 [SC]Found MRP parameters in the message
D: 139968 [SC]Including MRP parameters in PBKDF param response
I: 139974 [EM]<<< [E:15520r M:27434965] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 139986 [IN](U) Sending msg 27434965 to IP address 'BLE'
D: 139991 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 139999 [SC]Sent PBKDF param response
D: 140043 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 140050 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 140102 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 140111 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 140118 [EM]>>> [E:15520r M:54056485] (U) Msg RX from 0:C507A80039312A2A [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 140129 [EM]Found matching exchange: 15520r, Delegate: 0x20006634
D: 140135 [SC]Received spake2p msg1
I: 141687 [EM]<<< [E:15520r M:27434966] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 141698 [IN](U) Sending msg 27434966 to IP address 'BLE'
D: 141703 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 141711 [SC]Sent spake2p msg2
E: 141714 [DL]Long dispatch time: 1603 ms, for event type 16388
D: 141782 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 141790 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 141842 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 141851 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 141858 [EM]>>> [E:15520r M:54056486] (U) Msg RX from 0:C507A80039312A2A [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 141869 [EM]Found matching exchange: 15520r, Delegate: 0x20006634
D: 141875 [SC]Received spake2p msg3
D: 141879 [SC]Sending status report. Protocol code 0, exchange 15520
I: 141885 [EM]<<< [E:15520r M:27434967] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 141896 [IN](U) Sending msg 27434967 to IP address 'BLE'
D: 141901 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 141910 [SC]SecureSession[0x20004450]: Moving from state 'kEstablishing' --> 'kActive'
D: 141918 [IN]SecureSession[0x20004450]: Activated - Type:1 LSID:62705
D: 141924 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:62705 PSID:62938!
I: 141933 [SVR]Commissioning completed session establishment step
I: 141939 [DIS]Updating services using commissioning mode 0
D: 141944 [DL]Using Thread extended MAC for hostname.
D: 141949 [DL]Using Thread extended MAC for hostname.
I: 141954 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 141964 [DIS]Failed to advertise extended commissionable node: 3
D: 141970 [DIS]Scheduling extended discovery timeout in 900s
E: 141975 [DIS]Failed to finalize service update: 1c
D: 141980 [DL]CHIPoBLE advertising set to off
I: 141984 [SVR]Device completed Rendezvous process
E: 141988 [DL]Long dispatch time: 137 ms, for event type 16388
D: 141994 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142002 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142010 [EM]>>> [E:15521r M:181230691] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142020 [EM]Handling via exchange: 15521r, Delegate: 0x20010744
D: 142026 [IM]Received Read request
D: 142030 [DMG]IM RH moving to [GeneratingReports]
D: 142034 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142043 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 142048 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 142057 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 142063 [EM]<<< [E:15521r M:50775145] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142073 [IN](S) Sending msg 50775145 on secure session with LSID: 62705
D: 142080 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 142087 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142092 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142099 [DMG]IM RH moving to [AwaitingDestruction]
D: 142104 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142142 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142151 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142159 [EM]>>> [E:15522r M:181230692] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142169 [EM]Handling via exchange: 15522r, Delegate: 0x20010744
D: 142174 [IM]Received Read request
D: 142178 [DMG]IM RH moving to [GeneratingReports]
D: 142183 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142191 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 142197 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 142206 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 142212 [EM]<<< [E:15522r M:50775146] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142222 [IN](S) Sending msg 50775146 on secure session with LSID: 62705
D: 142228 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 142236 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142240 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142248 [DMG]IM RH moving to [AwaitingDestruction]
D: 142252 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142292 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142301 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142309 [EM]>>> [E:15523r M:181230693] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142319 [EM]Handling via exchange: 15523r, Delegate: 0x20010744
D: 142325 [IM]Received Read request
D: 142328 [DMG]IM RH moving to [GeneratingReports]
D: 142333 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142342 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty
D: 142347 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 142356 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 142362 [EM]<<< [E:15523r M:50775147] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142372 [IN](S) Sending msg 50775147 on secure session with LSID: 62705
D: 142378 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 142386 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142390 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142398 [DMG]IM RH moving to [AwaitingDestruction]
D: 142402 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142442 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142451 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142459 [EM]>>> [E:15524r M:181230694] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142469 [EM]Handling via exchange: 15524r, Delegate: 0x20010744
D: 142474 [IM]Received Read request
D: 142478 [DMG]IM RH moving to [GeneratingReports]
D: 142483 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142491 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty
D: 142497 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 142506 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 142512 [EM]<<< [E:15524r M:50775148] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142522 [IN](S) Sending msg 50775148 on secure session with LSID: 62705
D: 142528 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 142536 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142540 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142548 [DMG]IM RH moving to [AwaitingDestruction]
D: 142552 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142592 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142601 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142609 [EM]>>> [E:15525r M:181230695] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142619 [EM]Handling via exchange: 15525r, Delegate: 0x20010744
D: 142625 [IM]Received Read request
D: 142628 [DMG]IM RH moving to [GeneratingReports]
D: 142633 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142642 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 142647 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 142656 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 142662 [EM]<<< [E:15525r M:50775149] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142672 [IN](S) Sending msg 50775149 on secure session with LSID: 62705
D: 142678 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 142686 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142690 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142698 [DMG]IM RH moving to [AwaitingDestruction]
D: 142702 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142742 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142751 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 142759 [EM]>>> [E:15526r M:181230696] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 142769 [EM]Handling via exchange: 15526r, Delegate: 0x20010744
D: 142774 [IM]Received Read request
D: 142778 [DMG]IM RH moving to [GeneratingReports]
D: 142783 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 142791 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 142797 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 142806 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 142814 [EM]<<< [E:15526r M:50775150] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 142824 [IN](S) Sending msg 50775150 on secure session with LSID: 62705
D: 142831 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 142838 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 142843 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 142850 [DMG]IM RH moving to [AwaitingDestruction]
D: 142855 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 142893 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142900 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 142953 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 142960 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 143013 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 143020 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 143073 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 143081 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 143133 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 143141 [EM]>>> [E:15527r M:181230697] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 143151 [EM]Handling via exchange: 15527r, Delegate: 0x20010744
D: 143157 [IM]Received Read request
D: 143161 [DMG]IM RH moving to [GeneratingReports]
D: 143165 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 143174 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 143179 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 143188 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 143194 [EM]<<< [E:15527r M:50775151] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 143204 [IN](S) Sending msg 50775151 on secure session with LSID: 62705
D: 143211 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 143218 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 143223 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 143230 [DMG]IM RH moving to [AwaitingDestruction]
D: 143235 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 143253 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 144243 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 144251 [EM]>>> [E:15528r M:181230698] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 144261 [EM]Handling via exchange: 15528r, Delegate: 0x20010744
D: 144267 [DMG]Got Timed Request with timeout 10000: handler 0x20010b40 exchange 15528r
I: 144275 [EM]<<< [E:15528r M:50775152] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 144285 [IN](S) Sending msg 50775152 on secure session with LSID: 62705
D: 144292 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 144300 [DMG]Timed Request time limit 0x0000000000025ABC: handler 0x20010b40 exchange 15528r
D: 144392 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 144400 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 144408 [EM]>>> [E:15528r M:181230699] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 144419 [EM]Found matching exchange: 15528r, Delegate: 0x20010b40
D: 144425 [DMG]Timed following action arrived at 0x0000000000023429: handler 0x20010b40 exchange 15528r
D: 144434 [DMG]Handing timed invoke to IM engine: handler 0x20010b40 exchange 15528r
D: 144442 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 144450 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
D: 144456 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f46f1c3a
D: 144462 [DMG]Command handler moving to [ Preparing]
D: 144467 [DMG]Command handler moving to [AddingComm]
D: 144472 [DMG]Command handler moving to [AddedComma]
D: 144477 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 144484 [EM]<<< [E:15528r M:50775153] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 144495 [IN](S) Sending msg 50775153 on secure session with LSID: 62705
D: 144501 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 144509 [DMG]Command handler moving to [CommandSen]
D: 144514 [DMG]Command handler moving to [AwaitingDe]
E: 144519 [DL]Long dispatch time: 118 ms, for event type 16388
D: 144543 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 144551 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 144559 [EM]>>> [E:15529r M:181230700] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 144569 [EM]Handling via exchange: 15529r, Delegate: 0x20010744
D: 144575 [IM]Received Read request
D: 144579 [DMG]IM RH moving to [GeneratingReports]
D: 144583 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 144592 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 144597 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 144606 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 144612 [EM]<<< [E:15529r M:50775154] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 144622 [IN](S) Sending msg 50775154 on secure session with LSID: 62705
D: 144628 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 144636 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 144641 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 144648 [DMG]IM RH moving to [AwaitingDestruction]
D: 144653 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 144722 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 144731 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 144738 [EM]>>> [E:15530r M:181230701] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 144749 [EM]Handling via exchange: 15530r, Delegate: 0x20010744
D: 144755 [DMG]Got Timed Request with timeout 10000: handler 0x20010b40 exchange 15530r
I: 144763 [EM]<<< [E:15530r M:50775155] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 144773 [IN](S) Sending msg 50775155 on secure session with LSID: 62705
D: 144780 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 144787 [DMG]Timed Request time limit 0x0000000000025CA3: handler 0x20010b40 exchange 15530r
D: 144857 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 144866 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 144874 [EM]>>> [E:15530r M:181230702] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 144885 [EM]Found matching exchange: 15530r, Delegate: 0x20010b40
D: 144891 [DMG]Timed following action arrived at 0x00000000000235FB: handler 0x20010b40 exchange 15530r
D: 144900 [DMG]Handing timed invoke to IM engine: handler 0x20010b40 exchange 15530r
D: 144908 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 144918 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f46f1c3b
D: 144924 [DMG]Command handler moving to [ Preparing]
D: 144929 [DMG]Command handler moving to [AddingComm]
D: 144934 [DMG]Command handler moving to [AddedComma]
D: 144939 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 144946 [EM]<<< [E:15530r M:50775156] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 144957 [IN](S) Sending msg 50775156 on secure session with LSID: 62705
D: 144964 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 144971 [DMG]Command handler moving to [CommandSen]
D: 144976 [DMG]Command handler moving to [AwaitingDe]
E: 144981 [DL]Long dispatch time: 115 ms, for event type 16388
D: 145037 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145046 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 145054 [EM]>>> [E:15531r M:181230703] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 145065 [EM]Handling via exchange: 15531r, Delegate: 0x20010744
D: 145071 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 145079 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 145084 [DMG]Command handler moving to [ Preparing]
D: 145089 [DMG]Command handler moving to [AddingComm]
D: 145094 [DMG]Command handler moving to [AddedComma]
D: 145099 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 145108 [EM]<<< [E:15531r M:50775157] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 145119 [IN](S) Sending msg 50775157 on secure session with LSID: 62705
D: 145126 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145134 [DMG]Command handler moving to [CommandSen]
D: 145138 [DMG]Command handler moving to [AwaitingDe]
D: 145218 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145225 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145308 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145315 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145398 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145405 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145488 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145496 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 145503 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 145577 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145586 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 145594 [EM]>>> [E:15532r M:181230704] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 145605 [EM]Handling via exchange: 15532r, Delegate: 0x20010744
D: 145611 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 145618 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 145624 [DMG]Command handler moving to [ Preparing]
D: 145629 [DMG]Command handler moving to [AddingComm]
D: 145634 [DMG]Command handler moving to [AddedComma]
D: 145639 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 145648 [EM]<<< [E:15532r M:50775158] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 145659 [IN](S) Sending msg 50775158 on secure session with LSID: 62705
D: 145666 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145673 [DMG]Command handler moving to [CommandSen]
D: 145678 [DMG]Command handler moving to [AwaitingDe]
D: 145758 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145765 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145848 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145855 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 145982 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 145990 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146073 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146081 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 146088 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28)
D: 146207 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146216 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 146224 [EM]>>> [E:15533r M:181230705] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 146235 [EM]Handling via exchange: 15533r, Delegate: 0x20010744
D: 146241 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 146249 [ZCL]OpCreds: Received an AttestationRequest command
I: 146283 [ZCL]OpCreds: AttestationRequest successful.
D: 146288 [DMG]Command handler moving to [ Preparing]
D: 146293 [DMG]Command handler moving to [AddingComm]
D: 146298 [DMG]Command handler moving to [AddedComma]
D: 146303 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 146313 [EM]<<< [E:15533r M:50775159] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 146324 [IN](S) Sending msg 50775159 on secure session with LSID: 62705
D: 146331 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146338 [DMG]Command handler moving to [CommandSen]
D: 146343 [DMG]Command handler moving to [AwaitingDe]
E: 146348 [DL]Long dispatch time: 132 ms, for event type 16388
D: 146388 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146395 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146478 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146485 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146568 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146575 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146658 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146666 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 146673 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 146748 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146755 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90)
D: 146837 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 146846 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 146854 [EM]>>> [E:15534r M:181230706] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 146865 [EM]Handling via exchange: 15534r, Delegate: 0x20010744
D: 146871 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 146879 [ZCL]OpCreds: Received a CSRRequest command
D: 146884 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 147048 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 147083 [ZCL]OpCreds: CSRRequest successful.
D: 147087 [DMG]Command handler moving to [ Preparing]
D: 147092 [DMG]Command handler moving to [AddingComm]
D: 147097 [DMG]Command handler moving to [AddedComma]
D: 147102 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 147110 [EM]<<< [E:15534r M:50775160] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 147121 [IN](S) Sending msg 50775160 on secure session with LSID: 62705
D: 147128 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 147135 [DMG]Command handler moving to [CommandSen]
D: 147140 [DMG]Command handler moving to [AwaitingDe]
E: 147145 [DL]Long dispatch time: 299 ms, for event type 16388
D: 147198 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 147205 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 147288 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 147295 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 147378 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 148952 [DL]BLE GAP connection terminated (reason 0x13)
D: 148958 [IN]Clearing BLE pending packets.
I: 148962 [DL]Current number of connections: 0/2

Jeff

[AHaug]

Hi,

I've picked up your case and I'm working on getting you a reply. Hopefully I can give you an answer/more follow up questions at the start of the coming week.

Kind regards,
Andreas

[AHaug]

Hi,

I might've missed this from your logs, but I need to double check nonetheless. Did you register PID/VID to Google Developer Console? If not and this is your first try with Google I would recommend reading this article: https://devzone.nordicsemi.com/nordic/nordic-blog/b/blog/posts/matter-testing-nrf-connect-sdk-platform-with-apple-google-and-samsung-ecosystems-218911247 especially the "Commissioning of Matter over Thread Light Bulb to the Google Home ecosystem" part

 

Kind regards,
Andreas

[Jeffery]

Hi AHaug

Yes. I still saw this issue 100%.

There are two situations

1. GHA cannot find Matter-enabled device. Then, at the pop-up window, no "Matter" device can be selected. As same as the link you shared me, it's random. 

2. GHA can find Matter-enabled device. During commissioning, GHA terminated BLE connection.

At Samsung SmartThings, it works fine.

If you have further information from Google, pls shared it with me.

Thanks.

Jeff

[Jeffery]

Hi AHuag

At nrf Connect SDK documentation, Nordic likes to use Raspberry-Pi with CHIP-TOOL as a Matter controller and board router.

However, for me or for most users, it took time to install software and familiar with CHIP-TOOL.

Since Nordic solution was only for Matter device but not hub or gateway, why not to test commercial hub (like Google/Apple hubs) directly? 

How about your comment? Or, at mass production stage or QA testing, we can deploy CHIP-TOOL router as testing tool?

Jeff 

[AHaug]

I've queried the developers once again to see if they have heard anything since last time and to ask if they have any thoughts about why their test (with the parameters I mentioned) worked, while yours does not work.

Jeffery said:

At nrf Connect SDK documentation, Nordic likes to use Raspberry-Pi with CHIP-TOOL as a Matter controller and board router.

However, for me or for most users, it took time to install software and familiar with CHIP-TOOL.

Since Nordic solution was only for Matter device but not hub or gateway, why not to test commercial hub (like Google/Apple hubs) directly? 

One of the reasons for why the Rasoberry-Pi OpenThread Boarder-Router and CHIP-TOOL is the solution we're using is due to the amount of control we have over the router while we're testing. Using other proprietary, commercial solutions are limited w.r.t. debugging and having control over the features you want to implement which in turn will lead to restrictions for how far we're able to go w.r.t. give support to developers.

Jeffery said:

How about your comment? Or, at mass production stage or QA testing, we can deploy CHIP-TOOL router as testing tool?

Yes, you should be able to use a RPI OpenThread Boarder Router while testing if this is what you were asking.

Kind regards,
Andreas 

[AHaug]

AHaug said:

I've queried the developers once again to see if they have heard anything since last time and to ask if they have any thoughts about why their test (with the parameters I mentioned) worked, while yours does not work.

Some more information from the developers:

Recently we saw similar behavior as described in point no. 1. As a workaround we re-enabled BLE on our Android Phone and that issue was gone. We don't have any more details about that, as we haven't seen the issue again after that. In addition the answers in the google tickets are currently the best answers we have at this point in time.

In addition to the workaround mentioned above, we also suggest you to attempt to test this with another phone to check if the issue still exists. If it works with Samsung SmartThings (using the same phone) it means that there may be still something wrong with GHA and not with our SoC. 

Unfortunately we don't think this is a Nordic related issue, so we would like to recommend you to fill in the issue on the public issue tracker as well: https://developers.home.google.com/matter/support

Kind regards,
Andreas

[Jeffery]

Hi AHaug

I used another Android phone (Google Pixel4). The issue was same.

Home apps terminated BLE connection during commissioning process.

If you was informed some information about Google, please kindly let me know.

Jeff

[AHaug]

Noted, I will communicate that the issue is present with different phones as well.

AHaug said:

s a workaround we re-enabled BLE on our Android Phone and that issue was gone. We don't have any more details about that, as we haven't seen the issue again after that. In addition the answers in the google tickets are currently the best answers we have at this point in time.

Did the workaround fix anything for you?

Jeffery said:

If you was informed some information about Google, please kindly let me know.

I will inform you if we get any information about the Google related issue as soon as I get it

Kind regards,
Andreas

[Jeffery]

Hi AHaug

Google home apps was updated from 2.63.1.12 to 2.65.1.6.

I have tried new version if solving the commissioning issue.

New version can find Matter device and start commissioning.

It still terminate BLE connection but telling me the reason.

The reason was the device was not Matter qualified (No authorized DAC).

It was different to Samsung SmartThings. SmartThings allowed non Matter qualified device.

Did Nordic or Matter provide developer with test purposed DAC/PAI/...?

Thanks.

Jeff

 

[AHaug]

Hi,

The behaviour you're describing seems to be due to not adding the proper VID and PID to the dev console, so we're going back to my initial response to this case asking you to follow the blogpost devzone.nordicsemi.com/.../matter-testing-nrf-connect-sdk-platform-with-apple-google-and-samsung-ecosystems-218911247

More specifically users needs to create a Google Developer account and Matter integration in order to commission non-certified devices: developers.home.google.com/.../create

Apple, Amazon and Samsung do not have such requirement. In these ecosystems, we just got notification that device has not been certified - and so we need to click an "Approve" button.

You state that you've added VID and PID to the developer console, so we have two questions:

1. Which sample did you use and which VID/PID did you add to the console?
2. Is the Google account the same for the phone, Hub and the developer console? 

Let me know about these two answers and we'll see if these two things are the reason for why it does not work.

Kind regards,
Andreas

[Jeffery]

Hi AHaug

Did you try Google home ok?

The sample I tried was ncs2.3.0 light bulb at NRF5340 DK. Actually, I also tried door lock/light switch/window covering/weather station. They also failed to commission at Google home.

VID/PID is FFF1/8005. I didn't modify them at original sample code. 

I am sure added FFF1/8005 at my Google developer console as below.

Fullscreen 2043.log.txt Download

I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 17223 [TS]Pending Last Known Good Time: 2023-03-08T09:50:48
I: 17229 [TS]Previous Last Known Good Time: 2023-03-08T09:50:48
I: 17234 [TS]Reverted Last Known Good Time to previous value
I: 17240 [DL]Performing factory reset
I: 17249 [DL]Erasing Thread persistent info...


uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, e40
I: data wra: 0, f0
*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 167 [DL]BLE address: CD:25:ED:92:1C:D9
I: 189 [DL]OpenThread started: OK
I: 192 [DL]Setting OpenThread device type to ROUTER
I: 197 [SVR]Server initializing...
I: 200 [TS]Last Known Good Time: [unknown]
I: 204 [TS]Setting Last Known Good Time to firmware build time 2023-03-08T09:50:48
I: 213 [DMG]AccessControl: initializing
I: 216 [DMG]Examples::AccessControlDelegate::Init
I: 220 [DMG]AccessControl: setting
I: 224 [DMG]DefaultAclStorage: initializing
I: 228 [DMG]DefaultAclStorage: 0 entries loaded
D: 232 [IN]UDP::Init bind&listen port=5540
E: 236 [IN]SO_REUSEPORT failed: 109
D: 239 [IN]UDP::Init bound to port=5540
D: 242 [IN]BLEBase::Init - setting/overriding transport
D: 248 [IN]TransportMgr initialized
I: 255 [ZCL]Using ZAP configuration...
I: 261 [DMG]AccessControlCluster: initializing
I: 265 [ZCL]Initiating Admin Commissioning cluster.
I: 270 [ZCL]On/Off set value: 1 0
I: 273 [ZCL]On/off already set to new value
I: 278 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 285 [IN]SecureSession[0x20004428]: Allocated Type:1 LSID:21227
I: 291 [DIS]Updating services using commissioning mode 1
I: 297 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 306 [DIS]Failed to advertise commissionable node: 3
E: 311 [DIS]Failed to finalize service update: 1c
I: 315 [DIS]Updating services using commissioning mode 1
I: 321 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 330 [DIS]Failed to advertise commissionable node: 3
E: 335 [DIS]Failed to finalize service update: 1c
I: 339 [DIS]Delaying proxy of operational discovery: missing delegate
I: 346 [IN]CASE Server enabling CASE session setups
D: 350 [IN]SecureSession[0x200044e0]: Allocated Type:2 LSID:21228
I: 356 [SVR]Joining Multicast groups
I: 360 [SVR]Server Listening...
I: 363 [DL]Device Configuration:
I: 366 [DL]  Serial Number: 11223344556677889900
I: 370 [DL]  Vendor Id: 65521 (0xFFF1)
I: 373 [DL]  Product Id: 32773 (0x8005)
I: 377 [DL]  Hardware Version: 0
I: 380 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 386 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 393 [DL]  Manufacturing Date: (not set)
I: 396 [DL]  Device Type: 65535 (0xFFFF)
I: 400 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 405 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 411 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 420 [SVR]Manual pairing code: [34970112332]
I: 425 [DL]CHIP task running
I: 431 [DL]CHIPoBLE advertising started
I: 436 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 441 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 447 [DL]NFC Tag emulation started
I: 30435 [DL]CHIPoBLE advertising mode changed to slow
I: 30445 [DL]CHIPoBLE advertising started
I: BLE advertising is already enabled
I: BLE advertising is already enabled
I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 838924 [TS]Pending Last Known Good Time: 2023-03-08T09:50:48
I: 838930 [TS]Previous Last Known Good Time: 2023-03-08T09:50:48
I: 838936 [TS]Reverted Last Known Good Time to previous value
I: 838941 [DL]Performing factory reset
I: 838950 [DL]Erasing Thread persistent info...


uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, cb8
I: data wra: 0, 1cc
*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 167 [DL]BLE address: C8:46:EE:AA:14:3B
I: 189 [DL]OpenThread started: OK
I: 192 [DL]Setting OpenThread device type to ROUTER
I: 197 [SVR]Server initializing...
I: 200 [TS]Last Known Good Time: [unknown]
I: 204 [TS]Setting Last Known Good Time to firmware build time 2023-03-08T09:50:48
I: 213 [DMG]AccessControl: initializing
I: 216 [DMG]Examples::AccessControlDelegate::Init
I: 221 [DMG]AccessControl: setting
I: 224 [DMG]DefaultAclStorage: initializing
I: 228 [DMG]DefaultAclStorage: 0 entries loaded
D: 232 [IN]UDP::Init bind&listen port=5540
E: 236 [IN]SO_REUSEPORT failed: 109
D: 239 [IN]UDP::Init bound to port=5540
D: 243 [IN]BLEBase::Init - setting/overriding transport
D: 248 [IN]TransportMgr initialized
I: 255 [ZCL]Using ZAP configuration...
I: 261 [DMG]AccessControlCluster: initializing
I: 265 [ZCL]Initiating Admin Commissioning cluster.
I: 270 [ZCL]On/Off set value: 1 0
I: 273 [ZCL]On/off already set to new value
I: 278 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 285 [IN]SecureSession[0x20004428]: Allocated Type:1 LSID:13843
I: 291 [DIS]Updating services using commissioning mode 1
I: 297 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 306 [DIS]Failed to advertise commissionable node: 3
E: 311 [DIS]Failed to finalize service update: 1c
I: 315 [DIS]Updating services using commissioning mode 1
I: 321 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 330 [DIS]Failed to advertise commissionable node: 3
E: 335 [DIS]Failed to finalize service update: 1c
I: 339 [DIS]Delaying proxy of operational discovery: missing delegate
I: 346 [IN]CASE Server enabling CASE session setups
D: 351 [IN]SecureSession[0x200044e0]: Allocated Type:2 LSID:13844
I: 356 [SVR]Joining Multicast groups
I: 360 [SVR]Server Listening...
I: 363 [DL]Device Configuration:
I: 366 [DL]  Serial Number: 11223344556677889900
I: 370 [DL]  Vendor Id: 65521 (0xFFF1)
I: 374 [DL]  Product Id: 32773 (0x8005)
I: 377 [DL]  Hardware Version: 0
I: 381 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 386 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 393 [DL]  Manufacturing Date: (not set)
I: 396 [DL]  Device Type: 65535 (0xFFFF)
I: 400 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 405 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 411 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 420 [SVR]Manual pairing code: [34970112332]
I: 425 [DL]CHIP task running
I: 431 [DL]CHIPoBLE advertising started
I: 436 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 441 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 447 [DL]NFC Tag emulation started
I: 30435 [DL]CHIPoBLE advertising mode changed to slow
I: 30444 [DL]CHIPoBLE advertising started
I: 499796 [DL]BLE connection established (ConnId: 0x00)
I: 499801 [DL]Current number of connections: 1/1
I: 499806 [DL]CHIPoBLE advertising stopped
I: 499810 [DL]NFC Tag emulation stopped
I: 500902 [BLE]local and remote recv window sizes = 5
I: 500907 [BLE]selected BTP version 4
I: 500910 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 500925 [IN]BLE EndPoint 0x20012560 Connection Complete
I: 500930 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
I: 501187 [EM]>>> [E:19809r M:39201373] (U) Msg RX from 0:F2EEF69C25EDE0D0 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 501200 [EM]<<< [E:19809r M:99810487] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 501212 [IN](U) Sending msg 99810487 to IP address 'BLE'
I: 501368 [EM]>>> [E:19809r M:39201374] (U) Msg RX from 0:F2EEF69C25EDE0D0 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 502899 [EM]<<< [E:19809r M:99810488] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 502910 [IN](U) Sending msg 99810488 to IP address 'BLE'
E: 502916 [DL]Long dispatch time: 1548 ms, for event type 16388
I: 503078 [EM]>>> [E:19809r M:39201375] (U) Msg RX from 0:F2EEF69C25EDE0D0 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 503090 [EM]<<< [E:19809r M:99810489] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 503101 [IN](U) Sending msg 99810489 to IP address 'BLE'
I: 503107 [SC]SecureSession[0x20004428]: Moving from state 'kEstablishing' --> 'kActive'
D: 503115 [IN]SecureSession[0x20004428]: Activated - Type:1 LSID:13843
D: 503121 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:13843 PSID:25080!
I: 503130 [SVR]Commissioning completed session establishment step
I: 503136 [DIS]Updating services using commissioning mode 0
I: 503142 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 503152 [DIS]Failed to advertise extended commissionable node: 3
D: 503157 [DIS]Scheduling extended discovery timeout in 900s
E: 503163 [DIS]Failed to finalize service update: 1c
I: 503168 [SVR]Device completed Rendezvous process
I: 503174 [EM]>>> [E:19810r M:255810169] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503184 [IM]Received Read request
I: 503189 [EM]<<< [E:19810r M:64605829] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503199 [IN](S) Sending msg 64605829 on secure session with LSID: 13843
I: 503259 [EM]>>> [E:19811r M:255810170] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503269 [IM]Received Read request
I: 503274 [EM]<<< [E:19811r M:64605830] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503284 [IN](S) Sending msg 64605830 on secure session with LSID: 13843
I: 503349 [EM]>>> [E:19812r M:255810171] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503359 [IM]Received Read request
I: 503364 [EM]<<< [E:19812r M:64605831] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503374 [IN](S) Sending msg 64605831 on secure session with LSID: 13843
I: 503439 [EM]>>> [E:19813r M:255810172] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503449 [IM]Received Read request
I: 503454 [EM]<<< [E:19813r M:64605832] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503464 [IN](S) Sending msg 64605832 on secure session with LSID: 13843
I: 503529 [EM]>>> [E:19814r M:255810173] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503539 [IM]Received Read request
I: 503544 [EM]<<< [E:19814r M:64605833] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503554 [IN](S) Sending msg 64605833 on secure session with LSID: 13843
I: 503619 [EM]>>> [E:19815r M:255810174] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 503629 [IM]Received Read request
I: 503636 [EM]<<< [E:19815r M:64605834] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 503646 [IN](S) Sending msg 64605834 on secure session with LSID: 13843
I: 504068 [EM]>>> [E:19816r M:255810175] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 504078 [IM]Received Read request
I: 504083 [EM]<<< [E:19816r M:64605835] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 504093 [IN](S) Sending msg 64605835 on secure session with LSID: 13843
I: 514868 [EM]>>> [E:19817r M:255810176] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
I: 514879 [EM]<<< [E:19817r M:64605836] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 514889 [IN](S) Sending msg 64605836 on secure session with LSID: 13843
I: 514959 [EM]>>> [E:19817r M:255810177] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 514971 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 514977 [EM]<<< [E:19817r M:64605837] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 514988 [IN](S) Sending msg 64605837 on secure session with LSID: 13843
I: 515049 [EM]>>> [E:19818r M:255810178] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 515059 [IM]Received Read request
I: 515064 [EM]<<< [E:19818r M:64605838] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 515074 [IN](S) Sending msg 64605838 on secure session with LSID: 13843
I: 515139 [EM]>>> [E:19819r M:255810179] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
I: 515150 [EM]<<< [E:19819r M:64605839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 515160 [IN](S) Sending msg 64605839 on secure session with LSID: 13843
I: 515229 [EM]>>> [E:19819r M:255810180] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 515245 [EM]<<< [E:19819r M:64605840] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 515256 [IN](S) Sending msg 64605840 on secure session with LSID: 13843
I: 515319 [EM]>>> [E:19820r M:255810181] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 515330 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 515340 [EM]<<< [E:19820r M:64605841] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 515350 [IN](S) Sending msg 64605841 on secure session with LSID: 13843
I: 515769 [EM]>>> [E:19821r M:255810182] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 515780 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 515789 [EM]<<< [E:19821r M:64605842] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 515800 [IN](S) Sending msg 64605842 on secure session with LSID: 13843
I: 516219 [EM]>>> [E:19822r M:255810183] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 516231 [ZCL]OpCreds: Received an AttestationRequest command
I: 516266 [ZCL]OpCreds: AttestationRequest successful.
I: 516275 [EM]<<< [E:19822r M:64605843] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 516285 [IN](S) Sending msg 64605843 on secure session with LSID: 13843
I: 516804 [EM]>>> [E:19823r M:255810184] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 516816 [ZCL]OpCreds: Received a CSRRequest command
I: 516978 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 517013 [ZCL]OpCreds: CSRRequest successful.
I: 517019 [EM]<<< [E:19823r M:64605844] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 517030 [IN](S) Sending msg 64605844 on secure session with LSID: 13843
E: 517037 [DL]Long dispatch time: 234 ms, for event type 16388
I: 519821 [EM]>>> [E:19824r M:255810185] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 519832 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 519893 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 519899 [EM]<<< [E:19824r M:64605845] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 519911 [IN](S) Sending msg 64605845 on secure session with LSID: 13843
I: 520452 [EM]>>> [E:19825r M:255810186] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 520463 [ZCL]OpCreds: Received an AddNOC command
I: 520470 [FP]Validating NOC chain
I: 520583 [FP]NOC chain validation successful
I: 520587 [FP]Added new fabric at index: 0x1
I: 520591 [FP]Assigned compressed fabric ID: 0x1C094C8A23038269, node ID: 0x00000000EA5A9319
I: 520599 [TS]Last Known Good Time: 2023-03-08T09:50:48
I: 520604 [TS]New proposed Last Known Good Time: 2023-03-20T04:02:26
I: 520610 [TS]Updating pending Last Known Good Time to 2023-03-20T04:02:26
I: 520628 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
I: 520637 [DIS]Advertise operational node 1C094C8A23038269-00000000EA5A9319
I: 520644 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 520651 [EM]<<< [E:19825r M:64605846] (S) Msg TX to 1:FFFFFFFB00000000 [8269] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 520662 [IN](S) Sending msg 64605846 on secure session with LSID: 13843
E: 520669 [DL]Long dispatch time: 221 ms, for event type 16388
I: 520809 [EM]>>> [E:19826r M:255810187] (S) Msg RX from 1:FFFFFFFB00000000 [8269] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 520824 [EM]<<< [E:19826r M:64605847] (S) Msg TX to 1:FFFFFFFB00000000 [8269] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 520835 [IN](S) Sending msg 64605847 on secure session with LSID: 13843
I: 520899 [EM]>>> [E:19827r M:255810188] (S) Msg RX from 1:FFFFFFFB00000000 [8269] --- Type 0001:02 (IM:ReadRequest)
D: 520909 [IM]Received Read request
I: 520914 [EM]<<< [E:19827r M:64605848] (S) Msg TX to 1:FFFFFFFB00000000 [8269] --- Type 0001:05 (IM:ReportData)
I: 520924 [IN](S) Sending msg 64605848 on secure session with LSID: 13843
I: 520989 [EM]>>> [E:19828r M:255810189] (S) Msg RX from 1:FFFFFFFB00000000 [8269] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 521873 [DL]SRP Client was started, detected server: fd4a:66ba:47f8:0000:1cd1:e6f2:d913:6798
I: 521884 [EM]<<< [E:19828r M:64605849] (S) Msg TX to 1:FFFFFFFB00000000 [8269] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 521895 [IN](S) Sending msg 64605849 on secure session with LSID: 13843
I: 521902 [DIS]Advertise operational node 1C094C8A23038269-00000000EA5A9319
I: 521909 [SVR]Operational advertising enabled
I: 522235 [DIS]Setting operational delegate post init
I: 522243 [SWU]Stopping the watchdog timer
I: 522247 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 522254 [DIS]Updating services using commissioning mode 0
I: 522259 [DIS]Advertise operational node 1C094C8A23038269-00000000EA5A9319
I: 522266 [DL]advertising srp service: 1C094C8A23038269-00000000EA5A9319._matter._tcp
I: 522274 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 522284 [DL]advertising srp service: D097CD20915C1AC3._matterc._udp
I: 529942 [DL]BLE GAP connection terminated (reason 0x13)
I: 529948 [DL]Current number of connections: 0/1
E: 541998 [BLE]ack recv timeout, closing ep 0x20012560
D: 542003 [IN]Clearing BLE pending packets.
I: 542007 [BLE]Releasing end point's BLE connection back to application.
I: 542014 [DL]Closing BLE GATT connection (ConnId 00)

[CartBlanche]

I'm also interested in getting commissioning working for nRF52840 with both Apple and Google devices. Not had any luck either and getting the same error as you. Unsupported device, despise using the Google Console to sync the VID and PID. 

Posting here to keep track of any updates/replies :)