[MATTER] ZEPHYR FATAL error as commissioning to SmartThings apps

Hi Nordic team

- PCA10095 1.0.0 (NRF5340 DK board). ncs 2.2.0 light bulb/light switch/door lock/window covering samples at application core. 

  multiprotocol_rpmsg at network core.

- Aeotec SmartThings hub v3

- WiFi AP

- Latest SmartThings apps at smartphone (Samsung A52s, Android 13)

1. If DK board was PCA10056 (NRF52840 DK), all four samples can work that it means DK can be commissioned and be controlled at SmartThings apps.

2. If DK board was PCA10095 (NRF5340 DK), only light bulb sample can work. The other three samples failed at commissioning. The log as below showed

    fatal error and system halted at door lock sample.



uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, f58
I: data wra: 0, 90
*** Booting Zephyr OS build v3.2.99-ncs1 ***
I: Init CHIP stack
I: 165 [DL]BLE address: FE:D1:B6:82:93:A6
I: 186 [DL]OpenThread SED interval set to 1000ms
I: 191 [DL]OpenThread started: OK
I: 194 [DL]Setting OpenThread device type to SLEEPY END DEVICE
I: 200 [SVR]Server initializing...
D: 203 [FP]Initializing FabricTable from persistent storage
I: 209 [TS]Last Known Good Time: 2023-02-09T11:08:43
I: 214 [DMG]AccessControl: initializing
I: 217 [DMG]Examples::AccessControlDelegate::Init
I: 222 [DMG]AccessControl: setting
I: 225 [DMG]DefaultAclStorage: initializing
I: 229 [DMG]DefaultAclStorage: 0 entries loaded
D: 233 [IN]UDP::Init bind&listen port=5540
E: 237 [IN]SO_REUSEPORT failed: 109
D: 240 [IN]UDP::Init bound to port=5540
D: 244 [IN]BLEBase::Init - setting/overriding transport
D: 249 [IN]TransportMgr initialized
D: 253 [DL]Using Thread extended MAC for hostname.
I: 259 [ZCL]Using ZAP configuration...
D: 263 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
I: 270 [DMG]AccessControlCluster: initializing
D: 274 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3d
D: 281 [DL]Boot reason: 1
D: 283 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 287 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to a4722add
D: 294 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000125
I: 307 [ZCL]Initiating Admin Commissioning cluster.
I: 312 [ZCL]Door Lock server initialized
D: 315 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to e778dc20
I: 322 [ZCL]Door Lock cluster initialized at endpoint #1
D: 327 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc483
D: 333 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc484
D: 339 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc485
D: 345 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc486
D: 352 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc487
D: 358 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc488
D: 364 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc489
D: 371 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc48a
I: 377 [DIS]Updating services using commissioning mode 0
D: 382 [DL]Using Thread extended MAC for hostname.
D: 387 [DL]Using Thread extended MAC for hostname.
I: 391 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
E: 400 [DIS]Failed to advertise extended commissionable node: 3
D: 406 [DIS]Scheduling extended discovery timeout in 900s
E: 411 [DIS]Failed to finalize service update: 1c
I: 415 [DIS]Delaying proxy of operational discovery: missing delegate
I: 422 [IN]CASE Server enabling CASE session setups
D: 427 [IN]SecureSession[0x20004850]: Allocated Type:2 LSID:22668
D: 432 [SC]Allocated SecureSession (0x20004850) - waiting for Sigma1 msg
I: 439 [SVR]Joining Multicast groups
D: 442 [ZCL]Emitting StartUp event
D: 445 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001BD
I: 459 [SVR]Server Listening...
I: 462 [DL]Device Configuration:
I: 465 [DL]  Serial Number: 11223344556677889900
I: 469 [DL]  Vendor Id: 65521 (0xFFF1)
I: 473 [DL]  Product Id: 32774 (0x8006)
I: 476 [DL]  Hardware Version: 0
I: 479 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 485 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 491 [DL]  Manufacturing Date: (not set)
I: 495 [DL]  Device Type: 65535 (0xFFFF)
I: 499 [SVR]SetupQRCode: [MT:8IXS142C00KA0648G00]
I: 503 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 510 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A8IXS142C00KA0648G00
I: 518 [SVR]Manual pairing code: [34970112332]
I: 524 [DL]CHIP task running
I: 526 [DIS]Updating services using commissioning mode 0
D: 531 [DL]Using Thread extended MAC for hostname.
D: 536 [DL]Using Thread extended MAC for hostname.
I: 541 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
E: 550 [DIS]Failed to advertise extended commissionable node: 3
E: 555 [DIS]Failed to finalize service update: 1c
D: 560 [DMG]Endpoint 1, Cluster 0x0000_0101 update version to 7eddc48b
D: 42231 [IN]SecureSession[0x20004908]: Allocated Type:1 LSID:22669
D: 42237 [SC]Assigned local session key ID 22669
D: 42241 [SC]Waiting for PBKDF param request
D: 42245 [DL]CHIPoBLE advertising set to on
I: 42249 [DIS]Updating services using commissioning mode 1
D: 42255 [DL]Using Thread extended MAC for hostname.
D: 42260 [DL]Using Thread extended MAC for hostname.
I: 42265 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
E: 42274 [DIS]Failed to advertise commissionable node: 3
E: 42279 [DIS]Failed to finalize service update: 1c
I: 42287 [DL]CHIPoBLE advertising started
I: 42291 [DL]NFC Tag emulation started
I: 42481 [DL]BLE connection established (ConnId: 0x00)
I: 42486 [DL]Current number of connections: 1/2
I: 42491 [DL]CHIPoBLE advertising stopped
I: 42495 [DL]NFC Tag emulation stopped
D: 43017 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43024 [BLE]local and remote recv window sizes = 5
I: 43029 [BLE]selected BTP version 4
I: 43032 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 43107 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 43111 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 43119 [IN]BLE EndPoint 0x20010a28 Connection Complete
I: 43124 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 43167 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43175 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43183 [EM]>>> [E:24236r M:26347726] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 43194 [EM]Handling via exchange: 24236r, Delegate: 0x20006a34
D: 43200 [SC]Received PBKDF param request
D: 43204 [SC]Peer assigned session ID 53812
D: 43208 [SC]Found MRP parameters in the message
D: 43212 [SC]Including MRP parameters in PBKDF param response
I: 43218 [EM]<<< [E:24236r M:246000293] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 43230 [IN](U) Sending msg 246000293 to IP address 'BLE'
D: 43235 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 43243 [SC]Sent PBKDF param response
D: 43347 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43379 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43386 [EM]>>> [E:24236r M:26347727] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 43397 [EM]Found matching exchange: 24236r, Delegate: 0x20006a34
D: 43403 [SC]Received spake2p msg1
I: 44949 [EM]<<< [E:24236r M:246000294] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 44960 [IN](U) Sending msg 246000294 to IP address 'BLE'
D: 44965 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
D: 44973 [SC]Sent spake2p msg2
E: 44975 [DL]Long dispatch time: 1597 ms, for event type 16388
D: 45087 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45095 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45103 [EM]>>> [E:24236r M:26347728] (U) Msg RX from 0:6C6441EF3331B32B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 45114 [EM]Found matching exchange: 24236r, Delegate: 0x20006a34
D: 45120 [SC]Received spake2p msg3
D: 45123 [SC]Sending status report. Protocol code 0, exchange 24236
I: 45129 [EM]<<< [E:24236r M:246000295] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 45140 [IN](U) Sending msg 246000295 to IP address 'BLE'
D: 45145 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 45154 [SC]SecureSession[0x20004908]: Moving from state 'kEstablishing' --> 'kActive'
D: 45162 [IN]SecureSession[0x20004908]: Activated - Type:1 LSID:22669
D: 45168 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:22669 PSID:53812!
I: 45177 [SVR]Commissioning completed session establishment step
I: 45183 [DIS]Updating services using commissioning mode 0
D: 45188 [DL]Using Thread extended MAC for hostname.
D: 45193 [DL]Using Thread extended MAC for hostname.
I: 45198 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
E: 45208 [DIS]Failed to advertise extended commissionable node: 3
D: 45214 [DIS]Scheduling extended discovery timeout in 900s
E: 45219 [DIS]Failed to finalize service update: 1c
D: 45224 [DL]CHIPoBLE advertising set to off
I: 45228 [SVR]Device completed Rendezvous process
E: 45232 [DL]Long dispatch time: 137 ms, for event type 16388
D: 45238 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45245 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45253 [EM]>>> [E:24237r M:42699344] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 45263 [EM]Handling via exchange: 24237r, Delegate: 0x2000e3f4
D: 45269 [IM]Received Read request
D: 45273 [DMG]IM RH moving to [GeneratingReports]
D: 45278 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 45286 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 45291 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 45300 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 45305 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 45314 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 45320 [EM]<<< [E:24237r M:131709115] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 45330 [IN](S) Sending msg 131709115 on secure session with LSID: 22669
D: 45337 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
D: 45344 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 45349 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 45356 [DMG]IM RH moving to [AwaitingDestruction]
D: 45361 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 45417 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45425 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45433 [EM]>>> [E:24238r M:42699345] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 45443 [EM]Handling via exchange: 24238r, Delegate: 0x2000e3f4
D: 45449 [IM]Received Read request
D: 45453 [DMG]IM RH moving to [GeneratingReports]
D: 45457 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 45466 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty
D: 45471 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 45480 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 45486 [EM]<<< [E:24238r M:131709116] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 45496 [IN](S) Sending msg 131709116 on secure session with LSID: 22669
D: 45502 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 45510 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 45514 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 45521 [DMG]IM RH moving to [AwaitingDestruction]
D: 45526 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 45567 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45575 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45583 [EM]>>> [E:24239r M:42699346] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 45593 [EM]Handling via exchange: 24239r, Delegate: 0x2000e3f4
D: 45599 [IM]Received Read request
D: 45603 [DMG]IM RH moving to [GeneratingReports]
D: 45607 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 45616 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty
D: 45621 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 45630 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 45636 [EM]<<< [E:24239r M:131709117] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 45646 [IN](S) Sending msg 131709117 on secure session with LSID: 22669
D: 45652 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 45660 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 45664 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 45671 [DMG]IM RH moving to [AwaitingDestruction]
D: 45676 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 45717 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45725 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45733 [EM]>>> [E:24240r M:42699347] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 45743 [EM]Handling via exchange: 24240r, Delegate: 0x2000e3f4
D: 45749 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24240r
I: 45757 [EM]<<< [E:24240r M:131709118] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 45767 [IN](S) Sending msg 131709118 on secure session with LSID: 22669
D: 45774 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 45782 [DMG]Timed Request time limit 0x000000000000D9E6: handler 0x2000e7f0 exchange 24240r
D: 45837 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45845 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 45853 [EM]>>> [E:24240r M:42699348] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 45864 [EM]Found matching exchange: 24240r, Delegate: 0x2000e7f0
D: 45870 [DMG]Timed following action arrived at 0x000000000000B32E: handler 0x2000e7f0 exchange 24240r
D: 45879 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24240r
D: 45887 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 45894 [FS]GeneralCommissioning: Received ArmFailSafe (900s)
D: 45900 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3e
D: 45907 [DMG]Command handler moving to [ Preparing]
D: 45911 [DMG]Command handler moving to [AddingComm]
D: 45916 [DMG]Command handler moving to [AddedComma]
D: 45921 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 45928 [EM]<<< [E:24240r M:131709119] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45939 [IN](S) Sending msg 131709119 on secure session with LSID: 22669
D: 45945 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 45953 [DMG]Command handler moving to [CommandSen]
D: 45958 [DMG]Command handler moving to [AwaitingDe]
E: 45962 [DL]Long dispatch time: 117 ms, for event type 16388
D: 45987 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 45995 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 46003 [EM]>>> [E:24241r M:42699349] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 46014 [EM]Handling via exchange: 24241r, Delegate: 0x2000e3f4
D: 46020 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 46028 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 46034 [DMG]Command handler moving to [ Preparing]
D: 46038 [DMG]Command handler moving to [AddingComm]
D: 46043 [DMG]Command handler moving to [AddedComma]
D: 46048 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 46057 [EM]<<< [E:24241r M:131709120] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 46068 [IN](S) Sending msg 131709120 on secure session with LSID: 22669
D: 46075 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 46082 [DMG]Command handler moving to [CommandSen]
D: 46087 [DMG]Command handler moving to [AwaitingDe]
D: 46257 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46264 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 46437 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46445 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 46497 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46505 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 46513 [EM]>>> [E:24242r M:42699350] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 46524 [EM]Handling via exchange: 24242r, Delegate: 0x2000e3f4
D: 46530 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 46538 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 46544 [DMG]Command handler moving to [ Preparing]
D: 46548 [DMG]Command handler moving to [AddingComm]
D: 46553 [DMG]Command handler moving to [AddedComma]
D: 46558 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 46567 [EM]<<< [E:24242r M:131709121] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 46578 [IN](S) Sending msg 131709121 on secure session with LSID: 22669
D: 46585 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 46592 [DMG]Command handler moving to [CommandSen]
D: 46597 [DMG]Command handler moving to [AwaitingDe]
D: 46767 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46774 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 46947 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 46955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76)
D: 47037 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49257 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 51764 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 51822 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 54342 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 54659 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 54667 [EM]>>> [E:24243r M:42699351] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 54678 [EM]Handling via exchange: 24243r, Delegate: 0x2000e3f4
D: 54684 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 54691 [ZCL]OpCreds: Received a CSRRequest command
D: 54696 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 54859 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 54894 [ZCL]OpCreds: CSRRequest successful.
D: 54898 [DMG]Command handler moving to [ Preparing]
D: 54903 [DMG]Command handler moving to [AddingComm]
D: 54907 [DMG]Command handler moving to [AddedComma]
D: 54912 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 54921 [EM]<<< [E:24243r M:131709122] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 54931 [IN](S) Sending msg 131709122 on secure session with LSID: 22669
D: 54938 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 54946 [DMG]Command handler moving to [CommandSen]
D: 54950 [DMG]Command handler moving to [AwaitingDe]
E: 54955 [DL]Long dispatch time: 296 ms, for event type 16388
D: 55197 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 55205 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 137)
D: 55332 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 57672 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 59432 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 59519 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 59528 [EM]>>> [E:24244r M:42699352] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 59539 [EM]Handling via exchange: 24244r, Delegate: 0x2000e3f4
D: 59545 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 59552 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 59613 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 59618 [DMG]Command handler moving to [ Preparing]
D: 59623 [DMG]Command handler moving to [AddingComm]
D: 59627 [DMG]Command handler moving to [AddedComma]
D: 59632 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 59639 [EM]<<< [E:24244r M:131709123] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 59650 [IN](S) Sending msg 131709123 on secure session with LSID: 22669
D: 59657 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 59664 [DMG]Command handler moving to [CommandSen]
D: 59669 [DMG]Command handler moving to [AwaitingDe]
E: 59674 [DL]Long dispatch time: 155 ms, for event type 16388
D: 59742 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 59788 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 59882 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 59970 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 59981 [EM]>>> [E:24245r M:42699353] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 59992 [EM]Handling via exchange: 24245r, Delegate: 0x2000e3f4
D: 59998 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 60006 [ZCL]OpCreds: Received an AddNOC command
I: 60012 [FP]Validating NOC chain
I: 60124 [FP]NOC chain validation successful
I: 60128 [FP]Added new fabric at index: 0x1
I: 60132 [FP]Assigned compressed fabric ID: 0xFF6032CBA3F0E84E, node ID: 0x95314A8FC4458645
I: 60140 [TS]Last Known Good Time: 2023-02-09T11:08:43
I: 60145 [TS]New proposed Last Known Good Time: 2023-02-09T07:23:25
I: 60151 [TS]Retaining current Last Known Good Time
D: 60155 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981a
D: 60162 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981b
D: 60177 [EVL]LogEvent event number: 0x0000000000010002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000EB10
I: 60191 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00000001
D: 60199 [DL]Using Thread extended MAC for hostname.
I: 60204 [DIS]Advertise operational node FF6032CBA3F0E84E-95314A8FC4458645
D: 60211 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981c
D: 60217 [DMG]Endpoint 0, Cluster 0x0000_003E update version to a2f8981d
D: 60223 [DMG]Command handler moving to [ Preparing]
D: 60228 [DMG]Command handler moving to [AddingComm]
D: 60233 [DMG]Command handler moving to [AddedComma]
I: 60237 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 60244 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 60251 [EM]<<< [E:24245r M:131709124] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 60262 [IN](S) Sending msg 131709124 on secure session with LSID: 22669
D: 60268 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 60276 [DMG]Command handler moving to [CommandSen]
D: 60281 [DMG]Command handler moving to [AwaitingDe]
E: 60286 [DL]Long dispatch time: 315 ms, for event type 16388
D: 60327 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60335 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60343 [EM]>>> [E:24246r M:42699354] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:02 (IM:ReadRequest)
D: 60353 [EM]Handling via exchange: 24246r, Delegate: 0x2000e3f4
D: 60359 [IM]Received Read request
D: 60363 [DMG]IM RH moving to [GeneratingReports]
D: 60367 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 60376 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 60381 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 60390 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 60396 [EM]<<< [E:24246r M:131709125] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:05 (IM:ReportData)
I: 60406 [IN](S) Sending msg 131709125 on secure session with LSID: 22669
D: 60412 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 60420 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 60425 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 60432 [DMG]IM RH moving to [AwaitingDestruction]
D: 60436 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 60507 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61993 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 62000 [EM]>>> [E:24247r M:42699355] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest)
D: 62011 [EM]Handling via exchange: 24247r, Delegate: 0x2000e3f4
D: 62016 [DMG]Got Timed Request with timeout 15000: handler 0x2000e7f0 exchange 24247r
I: 62025 [EM]<<< [E:24247r M:131709126] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse)
I: 62035 [IN](S) Sending msg 131709126 on secure session with LSID: 22669
D: 62041 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 62049 [DMG]Timed Request time limit 0x0000000000012CF9: handler 0x2000e7f0 exchange 24247r
D: 62127 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62173 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 62181 [EM]>>> [E:24247r M:42699356] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 62191 [EM]Found matching exchange: 24247r, Delegate: 0x2000e7f0
D: 62197 [DMG]Timed following action arrived at 0x000000000000F2F5: handler 0x2000e7f0 exchange 24247r
D: 62207 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24247r
D: 62214 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0000
D: 62225 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 62233 [DL]OpenThread State Changed (Flags: 0x01009009)
D: 62238 [DL]   Network Name: OpenThread
D: 62242 [DL]   PAN Id: 0xE094
D: 62244 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
D: 62249 [DL]   Channel: 11
D: 62251 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 62256 [DL]   Thread Unicast Addresses:
D: 62260 [DL]        fe80::c82a:552b:c050:f12e/64 valid preferred
D: 64680 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 64737 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 65140 [DL]Thread Network: ST-3011016721 Panid 0xcebb Channel 20 RSSI -30 LQI 255 Version 4
D: 67105 [DL]OpenThread State Changed (Flags: 0x00008000)
D: 67110 [DL]   Network Name: OpenThread
D: 67114 [DL]   PAN Id: 0xFFFF
D: 67117 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
D: 67121 [DL]   Channel: 11
D: 67124 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 67129 [DMG]Command handler moving to [ Preparing]
D: 67134 [DMG]Command handler moving to [AddingComm]
D: 67139 [DMG]Command handler moving to [AddedComma]
D: 67143 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f3f
D: 67150 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 67157 [EM]<<< [E:24247r M:131709127] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 67168 [IN](S) Sending msg 131709127 on secure session with LSID: 22669
D: 67175 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 125)
D: 67182 [DMG]Command handler moving to [CommandSen]
D: 67187 [DMG]Command handler moving to [AwaitingDe]
D: 67192 [DL]OpenThread State Changed (Flags: 0x01002002)
D: 67197 [DL]   Thread Unicast Addresses:
D: 67257 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67302 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67348 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67355 [EM]>>> [E:24248r M:42699357] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest)
D: 67366 [EM]Handling via exchange: 24248r, Delegate: 0x2000e3f4
D: 67371 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24248r
I: 67380 [EM]<<< [E:24248r M:131709128] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse)
I: 67390 [IN](S) Sending msg 131709128 on secure session with LSID: 22669
D: 67396 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 67404 [DMG]Timed Request time limit 0x0000000000012E5C: handler 0x2000e7f0 exchange 24248r
D: 67482 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67491 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67499 [EM]>>> [E:24248r M:42699358] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 67510 [EM]Found matching exchange: 24248r, Delegate: 0x2000e7f0
D: 67516 [DMG]Timed following action arrived at 0x00000000000107BC: handler 0x2000e7f0 exchange 24248r
D: 67525 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24248r
D: 67532 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 67541 [DMG]Command handler moving to [ Preparing]
D: 67546 [DMG]Command handler moving to [AddingComm]
D: 67551 [DMG]Command handler moving to [AddedComma]
D: 67555 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 76c00f40
D: 67562 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 67569 [EM]<<< [E:24248r M:131709129] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 67580 [IN](S) Sending msg 131709129 on secure session with LSID: 22669
D: 67587 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 67594 [DMG]Command handler moving to [CommandSen]
D: 67599 [DMG]Command handler moving to [AwaitingDe]
E: 67604 [DL]Long dispatch time: 113 ms, for event type 16388
D: 67662 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67670 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67678 [EM]>>> [E:24249r M:42699359] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:0a (IM:TimedRequest)
D: 67688 [EM]Handling via exchange: 24249r, Delegate: 0x2000e3f4
D: 67694 [DMG]Got Timed Request with timeout 10000: handler 0x2000e7f0 exchange 24249r
I: 67702 [EM]<<< [E:24249r M:131709130] (S) Msg TX to 1:FFFFFFFB00000000 [E84E] --- Type 0001:01 (IM:StatusResponse)
I: 67713 [IN](S) Sending msg 131709130 on secure session with LSID: 22669
D: 67719 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 67727 [DMG]Timed Request time limit 0x0000000000012F9F: handler 0x2000e7f0 exchange 24249r
D: 67842 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67897 [EM]>>> [E:24249r M:42699360] (S) Msg RX from 1:FFFFFFFB00000000 [E84E] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 67908 [EM]Found matching exchange: 24249r, Delegate: 0x2000e7f0
D: 67914 [DMG]Timed following action arrived at 0x000000000001094A: handler 0x2000e7f0 exchange 24249r
D: 67923 [DMG]Handing timed invoke to IM engine: handler 0x2000e7f0 exchange 24249r
D: 67930 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 67946 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 67953 [DL]OpenThread State Changed (Flags: 0x1006c100)
D: 67958 [DL]   Network Name: OpenThread
D: 67961 [DL]   PAN Id: 0xCEBB
D: 67964 [DL]   Extended PAN Id: 0x9455CF8938B5C5F0
D: 67969 [DL]   Channel: 20
D: 67971 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 67976 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 67981 [DL]   Device Role: DETACHED
D: 67985 [DL]   Thread Unicast Addresses:
D: 67988 [DL]        fdde:ad00:beef:0:ad8f:b8b1:b1c0:6616/64 valid
D: 67994 [DL]        fe80::c82a:552b:c050:f12e/64 valid preferred
E: No response within timeout 500
ASSERTION FAIL [0] @ WEST_TOPDIR/zephyr/drivers/ieee802154/ieee802154_nrf5.c:1152
	802.15.4 serialization error: -5
E: r0/a1:  0x00000004  r1/a2:  0x00000480  r2/a3:  0x200087d0
E: r3/a4:  0x20014584 r12/ip:  0x00000000 r14/lr:  0x0002c06f
E:  xpsr:  0x61100000
E: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
E: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
E: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
E: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
E: fpscr:  0x00000000
E: Faulting instruction address (r15/pc): 0x0007e398
E: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
E: Current thread: 0x200087d0 (openthread)
E: Halting system

Jeff

Parents
  • Hello Jeff,

    As I see that you are explicitly mentioning that you got the multiprotocol_rpmsg running on the network core, how are you building and flashing the device?

    Regards,

    Elfving

  • Hi Elfving

    As ncs2.2.0 door lock sample, I tested two methods to program NRF5340.

    1. If using flash at VS code, I found commissioning was successfully.

       During programming, did multiprotocol_rpmsg hex be programmed to network core automatically?

    2. Considering easy and simple programming in production line further, I used two batched files to program NRF5340.

    step1. use batch net to program network core. The hex file was built form ncs2.2.0 multiprotocol_rpmsg sample.

    step2. use batch app to program application core. The hex file was built form ncs2.2.0 door lock sample.

    If using this method, the FATAL ERROR showed up during commissioning process,

    Could you help me check these two batch files. Thanks.

    hexfiles_5340_doorlock.rar

Reply
  • Hi Elfving

    As ncs2.2.0 door lock sample, I tested two methods to program NRF5340.

    1. If using flash at VS code, I found commissioning was successfully.

       During programming, did multiprotocol_rpmsg hex be programmed to network core automatically?

    2. Considering easy and simple programming in production line further, I used two batched files to program NRF5340.

    step1. use batch net to program network core. The hex file was built form ncs2.2.0 multiprotocol_rpmsg sample.

    step2. use batch app to program application core. The hex file was built form ncs2.2.0 door lock sample.

    If using this method, the FATAL ERROR showed up during commissioning process,

    Could you help me check these two batch files. Thanks.

    hexfiles_5340_doorlock.rar

Children
  • Jeffery said:
       During programming, did multiprotocol_rpmsg hex be programmed to network core automatically?

    Exactly. The VSC Flashing 'Action' programs both cores.

    Jeffery said:
    2. Considering easy and simple programming in production line further, I used two batched files to program NRF5340.

    What is flashed to the network core isn't the default multiprotocol_rpmsg. If you want to split up the programming of the two cores you can try the hex file created in the child image of the matter sample (ie. in /window_covering/build/multiprotocol_rpmsg/zephyr/zephyr.hex), that should work.

    Regards,

    Elfving

Related