It's not possible to proceed a firmware update of matter light switch example on nRF5340DK.
I use following SDKs / Repos
- nrfConnect SDK v2.0.2
- standalone zephyr SDK v0.14.2
- chip/matter repo @5caec5a5e6f40f727d1f9d3170ecb878e664fb42 (master branch)
My host system is a MacBook Pro, Apple M1 Mac, macOS Monterey Version 12.5.1
Following steps to reproduce my the behavior:
1. Build ota-provider
./scripts/examples/gn_build_example.sh examples/ota-provider-app/linux out/provider chip_config_network_layer_ble=false
2. Build chip-tool
./scripts/examples/gn_build_example.sh examples/chip-tool out/chip-tool
3. Build light-switch-app (nRFConnect @nRF5340DK) and flash
west build -b nrf5340dk_nrf5340_cpuapp
4. Form Thread-Network with OTBR
5. Commissioning the _light-switch-app_ --> nodeId = 0x100
sudo ./chip-tool pairing ble-thread 0x100 hex:<ot-netdata> 20202021 3840
6. Start the ota-provider-app with the firmware file to update
sudo ./chip-ota-provider-app -f /<path-to-your-matter-repo>/connectedhomeip/examples/light-switch-app/nrfconnect/build/zephyr/matter.ota
7. Commissioning the ota-provider --> nodeId = 1 (other nodeIds are more complicated / doesn't lead to a communication from the device to the ota-provider)
sudo ./chip-tool pairing onnetwork 1 20202021
8. Write default-ota-provider to light-switch-device
sudo ./chip-tool otasoftwareupdaterequestor write default-ota-providers '[{"fabricIndex": 1, "providerNodeID": 1, "endpoint": 0}]' 0x100 0 9. Set ACL for Ota-provider operate-access to all clusters
sudo ./chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": null}, {"fabricIndex": 1, "privilege": 3, "authMode": 2, "subjects": null, "targets": null}]' 1 010. Trigger the ota-firmware update via matter cli on physical light-switch-device
matter ota query
Output from device:
matter ota query I: 1719783 [SWU]Triggered immediate OTA query for fabric: 0x1 D: 1719788 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bcdfe56a D: 1719795 [EVL]LogEvent event number: 0x0000000000000006 priority: 1, endpoint id: 0x0 cluster id: 0x0000_002A event id: 3 I: 1719809 [SWU]Stopping the Periodic Query timer I: 1719814 [SWU]Starting the watchdog timer, timeout: 21600 seconds D: 1719820 [SWU]Establishing session to provider node ID 0x0000000000000001 on fabric index 1 D: 1719828 [CSM]FindOrEstablishSession: PeerId = [1:0000000000000001] D: 1719834 [CSM]FindOrEstablishSession: No existing OperationalSessionSetup instance found D: 1719843 [CTL]OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 I: 1719850 [DIS]Resolving 0DC0FE2595D6A4FE:0000000000000001 ... uart:~$ I: 1720051 [DIS]Checking node lookup status after 201 ms I: 1720562 [DIS]Node ID resolved for 0DC0FE2595D6A4FE:0000000000000001 D: 1720568 [DIS] Hostname: F4D488602D4F D: 1720572 [DIS] IP Address #1: 2a00:6020:4398:7d00:c14:bd5:e797:34b6 D: 1720578 [DIS] Port: 5540 D: 1720581 [DIS] Mrp Interval idle: 5000 ms D: 1720584 [DIS] Mrp Interval active: 2000 ms D: 1720589 [DIS] TCP Supported: 1 D: 1720592 [DIS]Lookup clearing interface for non LL address I: 1720597 [DIS]UDP:[2a00:6020:4398:7d00:c14:bd5:e797:34b6]:5540: new best score: 5 I: 1720605 [DIS]Checking node lookup status after 754 ms D: 1720610 [DIS]OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[2a00:6020:4398:7d00:c14:bd5:e72 D: 1720623 [CTL]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 D: 1720631 [IN]SecureSession[0x200047e8]: Allocated Type:2 LSID:27118 I: 1720637 [SC]Initiating session on local FabricIndex 1 from 0x0000000000000100 -> 0x0000000000000001 D: 1720780 [SC]Including MRP parameters I: 1720784 [IN]Prepared unauthenticated message 0x200061f4 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on. I: 1720799 [IN]Sending unauthenticated msg 0x200061f4 with MessageCounter:247485674 to 0x0000000000000000 at monotonic timec I: 1720815 [DL]OpenThread SED interval set to 200ms I: 1720819 [SC]Sent Sigma1 msg D: 1720822 [CTL]OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 E: 1720831 [DL]Long dispatch time: 268 ms, for event type 2 D: 1726822 [EM]Retransmitting MessageCounter:247485674 on exchange 11032i Send Cnt 1 I: 1726830 [IN]Sending unauthenticated msg 0x200061f4 with MessageCounter:247485674 to 0x0000000000000000 at monotonic timec D: 1732774 [EM]Retransmitting MessageCounter:247485674 on exchange 11032i Send Cnt 2 I: 1732782 [IN]Sending unauthenticated msg 0x200061f4 with MessageCounter:247485674 to 0x0000000000000000 at monotonic timec D: 1743100 [EM]Retransmitting MessageCounter:247485674 on exchange 11032i Send Cnt 3 I: 1743108 [IN]Sending unauthenticated msg 0x200061f4 with MessageCounter:247485674 to 0x0000000000000000 at monotonic timec D: 1760557 [EM]Retransmitting MessageCounter:247485674 on exchange 11032i Send Cnt 4 I: 1760565 [IN]Sending unauthenticated msg 0x200061f4 with MessageCounter:247485674 to 0x0000000000000000 at monotonic timec E: 1775784 [SC]CASESession timed out while waiting for a response from the peer. Current state was 1 D: 1775793 [IN]SecureSession[0x200047e8]: Released - Type:2 LSID:27118 E: 1775799 [SWU]Failed to connect to node 0x0000000000000001: 32 D: 1775805 [EVL]LogEvent event number: 0x0000000000000007 priority: 1, endpoint id: 0x0 cluster id: 0x0000_002A event id: D D: 1775819 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bcdfe56b D: 1775826 [EVL]LogEvent event number: 0x0000000000000008 priority: 1, endpoint id: 0x0 cluster id: 0x0000_002A event id: 2 I: 1775841 [SWU]Unknown idle state reason so set the periodic timer for a next attempt I: 1775848 [SWU]Stopping the watchdog timer I: 1775852 [SWU]Starting the periodic query timer, timeout: 86400 seconds
Output from ota-provider:
[1663060359299] [8042:67029] CHIP: [EM] Received message of type 0x30 with protocolId (0, 0) and MessageCounter:247485674 on exchange 11032r [1663060359300] [8042:67029] CHIP: [EM] Handling via exchange: 11032r, Delegate: 0x104bce628 [1663060359300] [8042:67029] CHIP: [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x600002930180 [1663060359300] [8042:67029] CHIP: [IN] CASE Server disabling CASE session setups [1663060359300] [8042:67029] CHIP: [SC] Received Sigma1 msg [1663060359300] [8042:67029] CHIP: [SC] Found MRP parameters in the message [1663060359300] [8042:67029] CHIP: [SC] Peer assigned session key ID 27118 [1663060359302] [8042:67029] CHIP: [SC] CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 [1663060359306] [8042:67029] CHIP: [SC] Including MRP parameters [1663060359306] [8042:67029] CHIP: [EM] Piggybacking Ack for MessageCounter:247485674 on exchange: 11032r [1663060359306] [8042:67029] CHIP: [IN] Prepared unauthenticated message 0x600000728728 to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 11032r with MessageCounter:15789315. [1663060359306] [8042:67029] CHIP: [IN] Sending unauthenticated msg 0x600000728728 with MessageCounter:15789315 to 0x0000000000000000 at monotonic time: 00000000004A2252 msec [1663060359306] [8042:67029] CHIP: [SC] Sent Sigma2 msg [1663060359929] [8042:74588] CHIP: [EM] Retransmitting MessageCounter:15789315 on exchange 11032r Send Cnt 1 [1663060359929] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x600000728728 with MessageCounter:15789315 to 0x0000000000000000 at monotonic time: 00000000004A24C1 msec [1663060360486] [8042:74588] CHIP: [EM] Retransmitting MessageCounter:15789315 on exchange 11032r Send Cnt 2 [1663060360486] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x600000728728 with MessageCounter:15789315 to 0x0000000000000000 at monotonic time: 00000000004A26EE msec [1663060361390] [8042:74588] CHIP: [EM] Retransmitting MessageCounter:15789315 on exchange 11032r Send Cnt 3 [1663060361391] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x600000728728 with MessageCounter:15789315 to 0x0000000000000000 at monotonic time: 00000000004A2A77 msec [1663060362923] [8042:67029] CHIP: [EM] Retransmitting MessageCounter:15789315 on exchange 11032r Send Cnt 4 [1663060362923] [8042:67029] CHIP: [IN] Sending unauthenticated msg 0x600000728728 with MessageCounter:15789315 to 0x0000000000000000 at monotonic time: 00000000004A3073 msec [1663060365315] [8042:74588] CHIP: [IN] Received a duplicate message with MessageCounter:247485674 on exchange 11032r [1663060365315] [8042:74588] CHIP: [EM] Received message of type 0x30 with protocolId (0, 0) and MessageCounter:247485674 on exchange 11032r [1663060365315] [8042:74588] CHIP: [EM] Found matching exchange: 11032r, Delegate: 0x104bce660 [1663060365315] [8042:74588] CHIP: [EM] Forcing tx of solitary ack for duplicate MessageCounter:247485674 on exchange 11032r [1663060365315] [8042:74588] CHIP: [EM] Sending Standalone Ack for MessageCounter:247485674 on exchange 11032r [1663060365315] [8042:74588] CHIP: [IN] Prepared unauthenticated message 0x30df36508 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 11032r with MessageCounter:15789316. [1663060365315] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x30df36508 with MessageCounter:15789316 to 0x0000000000000000 at monotonic time: 00000000004A39CB msec [1663060365418] [8042:67029] CHIP: [EM] Failed to Send CHIP MessageCounter:15789315 on exchange 11032r sendCount: 4 max retries: 4 [1663060371262] [8042:74588] CHIP: [IN] Received a duplicate message with MessageCounter:247485674 on exchange 11032r [1663060371263] [8042:74588] CHIP: [EM] Received message of type 0x30 with protocolId (0, 0) and MessageCounter:247485674 on exchange 11032r [1663060371263] [8042:74588] CHIP: [EM] Found matching exchange: 11032r, Delegate: 0x104bce660 [1663060371263] [8042:74588] CHIP: [EM] Forcing tx of solitary ack for duplicate MessageCounter:247485674 on exchange 11032r [1663060371263] [8042:74588] CHIP: [EM] Sending Standalone Ack for MessageCounter:247485674 on exchange 11032r [1663060371263] [8042:74588] CHIP: [IN] Prepared unauthenticated message 0x30df36508 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 11032r with MessageCounter:15789317. [1663060371263] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x30df36508 with MessageCounter:15789317 to 0x0000000000000000 at monotonic time: 00000000004A5107 msec [1663060381597] [8042:74588] CHIP: [IN] Received a duplicate message with MessageCounter:247485674 on exchange 11032r [1663060381597] [8042:74588] CHIP: [EM] Received message of type 0x30 with protocolId (0, 0) and MessageCounter:247485674 on exchange 11032r [1663060381597] [8042:74588] CHIP: [EM] Found matching exchange: 11032r, Delegate: 0x104bce660 [1663060381597] [8042:74588] CHIP: [EM] Forcing tx of solitary ack for duplicate MessageCounter:247485674 on exchange 11032r [1663060381597] [8042:74588] CHIP: [EM] Sending Standalone Ack for MessageCounter:247485674 on exchange 11032r [1663060381597] [8042:74588] CHIP: [IN] Prepared unauthenticated message 0x30df36508 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 11032r with MessageCounter:15789318. [1663060381597] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x30df36508 with MessageCounter:15789318 to 0x0000000000000000 at monotonic time: 00000000004A7965 msec [1663060399047] [8042:74588] CHIP: [IN] Received a duplicate message with MessageCounter:247485674 on exchange 11032r [1663060399047] [8042:74588] CHIP: [EM] Received message of type 0x30 with protocolId (0, 0) and MessageCounter:247485674 on exchange 11032r [1663060399047] [8042:74588] CHIP: [EM] Found matching exchange: 11032r, Delegate: 0x104bce660 [1663060399047] [8042:74588] CHIP: [EM] Forcing tx of solitary ack for duplicate MessageCounter:247485674 on exchange 11032r [1663060399047] [8042:74588] CHIP: [EM] Sending Standalone Ack for MessageCounter:247485674 on exchange 11032r [1663060399047] [8042:74588] CHIP: [IN] Prepared unauthenticated message 0x30df36508 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 11032r with MessageCounter:15789319. [1663060399047] [8042:74588] CHIP: [IN] Sending unauthenticated msg 0x30df36508 with MessageCounter:15789319 to 0x0000000000000000 at monotonic time: 00000000004ABD8F msec [1663060409308] [8042:74588] CHIP: [SC] CASESession timed out while waiting for a response from the peer. Current state was 2 [1663060409309] [8042:74588] CHIP: [IN] CASE Session establishment failed: ../connectedhomeip/examples/ota-provider-app/linux/third_party/connectedhomeip/src/protocols/secure_channel/CASESession.cpp:290: CHIP Error 0x00000032: Timeout [1663060409309] [8042:74588] CHIP: [IN] CASE Server enabling CASE session setups [1663060409309] [8042:74588] CHIP: [IN] SecureSession[0x600003808000]: Released - Type:2 LSID:22827 [1663060409309] [8042:74588] CHIP: [IN] SecureSession[0x60000380c000]: Allocated Type:2 LSID:22828 [1663060409309] [8042:74588] CHIP: [SC] Allocated SecureSession (0x60000380c000) - waiting for Sigma1 msg
