[MGM240P] issue with matter_lightbulb_multiple_color.ino -> Not responding

[lboue]

Matter matter_lightbulb_multiple_color.ino Not responding after pairing

Hello
I am facing an issue with Matter matter_lightbulb_multiple_color.ino example. After pairing, device is not responding.

Steps to reproduce

1. Flash matter_lightbulb_multiple_color.ino to SparkFun Thing Plus MGM240P board
2. Pair it with Apple Home
3. Check Matter device status in Apple Home ==> Device is not responding

[lboue]

For context, this is my setup:

• Thead BR
  • 2 * AppleTV 4K
  • 1 * HomePod mini
• two Nordic nRF5340 boards that work without a problem with Matter over Thread
• 2 * Eve Energy smartplug
• 1 * Eve motion sensor

Serial monitor log

17:23:56.665 -> Matter multiple lightbulbs
17:23:57.214 -> Waiting for network connection...
17:23:57.418 -> Device connected
17:23:57.419 -> Dimmable bulb brightness changed to 20%

[lboue]

Same issue with another one: matter_lightbulb.ino

Serial monitor log

18:54:28.649 -> Matter lightbulb
19:00:47.749 -> Matter device is not commissioned
19:00:47.749 -> Commission it to your Matter hub with the manual pairing code or QR code
19:00:47.749 -> Manual pairing code: 34970112332
19:00:47.749 -> QR code URL: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
19:04:13.475 -> Waiting for network connection...
19:04:14.438 -> Device connected

Nothing happens when I try to switch on/off the device.

I took 6 min to change the lightbulb status in the console log. There's a big latency problem.

19:04:14.438 -> Device connected
19:10:41.775 -> Bulb ON
19:13:41.922 -> Bulb OFF
19:15:43.045 -> Bulb ON
19:22:21.939 -> Bulb OFF
19:25:21.837 -> Bulb ON

[lboue]

Is it possible to enable a verbose mode to identify the root cause?

[silabs-bozont]

Hello Iboue,
Glad it eventually started working - but you're right, it should not take 6 minutes to get synced.
Verbose logs from the Matter and Thread stack are available through RTT. You can read them with Segger's JLinkRTTViewer.
Start the RTT viewer and select the MGM240PB32VNA MCU:

Hit the reset on your board, then connect the RTT viewer to it. Your device should work as normal, wait for it to get synced and control the lightbulb a few times if possible. Please post the RTT logs from your device and we'll see what can cause it.

[lboue]

Hit the reset on your board, then connect the RTT viewer to it. Your device should work as normal, wait for it to get synced and control the lightbulb a few times if possible. Please post the RTT logs from your device and we'll see what can cause it.

I did the test. Here are the results.

J-Link RTT

[00:00:00.000][silabs ]==================================================
[00:00:00.000][silabs ]Arduino Matter device starting
[00:00:00.000][silabs ]==================================================
[00:00:00.000][silabs ]Init CHIP Stack
[00:00:00.000][silabs ]Initializing OpenThread stack
[00:00:00.000][info  ][DL] OpenThread started: OK
[00:00:00.000][info  ][DL] Setting OpenThread device type to ROUTER
[00:00:00.000][silabs ]Starting OpenThread task
[00:00:00.000][info  ][SVR] Subscription persistence not supported
[00:00:00.000][info  ][SVR] Server initializing...
[00:00:00.000][detail][FP] Initializing FabricTable from persistent storage
[00:00:00.000][info  ][TS] Last Known Good Time: 2024-02-07T19:01:23
[00:00:00.000][info  ][DMG] Acce

Serial log

22:14:03.310 -> Matter lightbulb
22:14:03.803 -> Matter device is not commissioned
22:14:03.803 -> Commission it to your Matter hub with the manual pairing code or QR code
22:14:03.803 -> Manual pairing code: 34970112332
22:14:03.803 -> QR code URL: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
22:14:53.656 -> Waiting for network connection...
22:14:55.226 -> Device connected
22:23:18.117 -> Bulb ON

J-Link RTT is useless in that case.

[silabs-bozont]

Thanks for the logs and the screenshots!
Looks like your RTT log is cut super short - it should print a LOT of messages. Please make sure that you first reset your board, then connect it to the RTT viewer. Once the board is connected reset shouldn't be issued as it will not automatically connect back.

[lboue]

Serial logs

13:37:21.033 -> Matter lightbulb
13:37:21.569 -> Matter device is not commissioned
13:37:21.569 -> Commission it to your Matter hub with the manual pairing code or QR code
13:37:21.569 -> Manual pairing code: 34970112332
13:37:21.569 -> QR code URL: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
13:41:09.708 -> Waiting for network connection...
13:41:11.342 -> Device connected
13:48:52.895 -> Bulb ON
13:50:09.116 -> Matter lightbulb
13:50:09.283 -> Waiting for network connection...
13:50:09.516 -> Device connected
13:52:53.028 -> Bulb ON
13:54:53.056 -> Bulb OFF
13:57:53.162 -> Bulb ON

Here is the RTT log:
matter_lightbulb_JRTT_13h50.log

Last lines

[00:11:29.190][detail][DMG] Fetched 0 events
[00:11:29.191][detail][DMG] <RE> Sending report (payload has 11 bytes)...
[00:11:29.191][info  ][EM] <<< [E:50630i S:26480 M:250142665] (S) Msg TX to 1:00000000212740BC [FE0B] --- Type 0001:05 (IM:ReportData)
[00:11:29.192][info  ][IN] (S) Sending msg 250142665 on secure session with LSID: 26480
[00:11:29.192][detail][DMG] IM RH moving to [AwaitingReportResponse]
[00:11:29.192][info  ][DMG] Refresh Subscribe Sync Timer with min 0 seconds and max 60 seconds
[00:11:29.192][detail][DMG] <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[00:11:29.193][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:11:29.193][detail][DMG] Unblock report hold after min 0 seconds
[00:11:29.216][detail][IN] UDP Message Received packet nb : 103 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 42
[00:11:29.217][info  ][EM] >>> [E:50630i S:26480 M:70711547 (Ack:250142665)] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0001:01 (IM:StatusResponse)
[00:11:29.217][detail][EM] Found matching exchange: 50630i, Delegate: 0x20008644
[00:11:29.217][detail][EM] Rxd Ack; Removing MessageCounter:250142665 from Retrans Table on exchange 50630i
[00:11:29.218][info  ][IM] Received status response, status is 0x00
[00:11:29.218][detail][DMG] <RE> OnReportConfirm: NumReports = 0
[00:11:29.218][detail][DMG] IM RH moving to [GeneratingReports]
[00:11:29.219][info  ][EM] <[00:11:31.337][detail][IN] UDP Message Received packet nb : 104 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 59
[00:11:31.338][info  ][EM] >>> [E:20897r S:26480 M:70711548] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0001:08 (IM:InvokeCommandRequest)
[00:11:31.338][detail][EM] Handling via exchange: 20897r, Delegate: 0x20006b9c
[00:11:31.339][detail][DMG] Received command for Endpoint=3 Cluster=0x0000_0006 Command=0x0000_0001
[00:11:31.339][info  ][DL] emberAfExternalAttributeReadCallback
[00:11:31.339][info  ][DL] HandleReadLightbulbAttribute: clusterId=6 attrId=0
[00:11:31.339][info  ][ZCL] Toggle ep3 on/off from state 0 to 1
[00:11:31.340][info  ][DL] emberAfExter[00:11:31.341][detail][DMG] Command handler moving to [ Preparing]
[00:11:31.341][detail][DMG] Command handler moving to [AddingComm]
[00:11:31.341][detail][DMG] Command handler moving to [[00:11:31.351][detail][DMG] Fetched 0 events
[00:11:31.351][detail][DMG] <RE> Sending report (payload has 39 bytes)...
[00:11:31.352][info  ][EM] <<< [E:50631i S:26480 M:250142668] (S) Msg TX to 1:00000000212740BC [FE0B] --- Type 0001:05 (IM:ReportData)
[00:11:31.352][info  ][IN] (S) Sending msg 250142668 on secure session with LSID: 26480
[00:11:31.353][detail][DMG] IM RH moving to [AwaitingReportResponse]
[00:11:31.353][info  ][DMG] Refresh Subscribe Sync Timer with min 0 seconds and max 60 seconds
[00:11:31.354][detail][DMG] <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[00:11:31.354][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:11:31.354][detail][DMG] Unblock report hold after min 0 seconds
[00:11:31.374][detail][IN] UDP Message Received packet nb : 105 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 34
[00:11:31.375][info  ][EM] >>> [E:20897r S:26480 M:70711549 (Ack:250142667)] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0000:10 (SecureChannel:StandaloneAck)
[00:11:31.375][detail][EM] Found matching exchange: 20897r, Delegate: 0
[00:11:31.375][detail][EM] Rxd Ack; Removing MessageCounter:250142667 from Retrans Table on exchange 20897r
[00:11:31.384][detail][IN] UDP Message Received packet nb : 106 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 42
[00:11:31.384][info  ][EM] >>> [E:50631i S:26480 M:70711550 (Ack:250142668)] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0001:01 (IM:StatusResponse)
[00:11:31.385][detail][EM] Found matching exchange: 50631i, Delegate: 0x20008644
[00:11:31.385][detail][EM] Rxd Ack; Removing MessageCounter:250142668 from Retrans Table on exchange 50631i
[00:11:31.385][info  ][IM] Received status response, status is 0x00
[00:11:31.385][detail][DMG] <RE> OnReportConfirm: NumReports = 0
[00:11:31.385][detail][DMG] IM RH moving to [GeneratingReports]
[00:11:31.386][info  ][EM] <[00:11:31.387][detail][EM] Flushed pending ack for MessageCounter:70711550 on exchange 50631i
[00:12:31.360][detail][IN] UDP Message Received packet nb : 107 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 59
[00:12:31.361][info  ][EM] >>> [E:20900r S:26480 M:70711551] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0001:08 (IM:InvokeCommandRequest)
[00:12:31.361][detail][EM] Handling via exchange: 20900r, Delegate: 0x20006b9c
[00:12:31.362][detail][DMG] Received command for Endpoint=3 Cluster=0x0000_0006 Command=0x0000_0001
[00:12:31.362][info  ][DL] emberAfExternalAttributeReadCallback
[00:12:31.362][info  ][DL] HandleReadLightbulbAttribute: clusterId=6 attrId=0
[00:12:31.362][info  ][ZCL] Endpoint 3 On/off already set to new value
[00:12:31.362][detail][DMG] Comm[00:12:31.364][info  ][IN] (S) Sending msg 250142670 on secure session with LSID: 26480
[00:12:31.365][detail][DMG] Command handler moving to [CommandSen]
[00:12:31.365][detail][DMG] Comman[00:12:31.372][detail][DMG] <RE> Sending report (payload has 11 bytes)...
[00:12:31.373][info  ][EM] <<< [E:50632i S:26480 M:250142671] (S) Msg TX to 1:00000000212740BC [FE0B] --- Type 0001:05 (IM:ReportData)
[00:12:31.373][info  ][IN] (S) Sending msg 250142671 on secure session with LSID: 26480
[00:12:31.373][detail][DMG] IM RH moving to [AwaitingReportResponse]
[00:12:31.374][info  ][DMG] Refresh Subscribe Sync Timer with min 0 seconds and max 60 seconds
[00:12:31.374][detail][DMG] <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[00:12:31.375][detail][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:12:31.375][detail][00:12:31.390][detail][IN] UDP Message Received packet nb : 108 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 34
[00:12:31.391][info  ][EM] >>> [E:20900r S:26480 M:70711552 (Ack:250142670)] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0000:10 (SecureChannel:StandaloneAck)
[00:12:31.391][detail][EM] Found matching exchange: 20900r, Delegate: 0
[00:12:31.391][detail][EM] Rxd Ack; Removing MessageCounter:250142670 from Retrans Table on exchange 20900r
[00:12:31.405][detail][IN] UDP Message Received packet nb : 109 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 42
[00:12:31.406][info  ][EM] >>> [E:50632i S:26480 M:70711553 (Ack:250142671)] (S) Msg RX from 1:00000000212740BC [FE0B] --- Type 0001:01 (IM:StatusResponse)
[00:12:31.406][detail][EM] Found matching exchange: 50632i, Delegate: 0x20008644
[00:12:31.406][detail][EM] Rxd Ack; Removing MessageCounter:250142671 from Retrans Table on exchange 50632i
[00:12:31.407][info  ][IM] Received status response, status is 0x00
[00:12:31.407][detail][DMG] <RE> OnReportConfirm: NumReports = 0
[00:12:31.407][detail][DMG] IM RH moving to [GeneratingReports]
[00:12:31.408][info  ][EM] <[00:12:31.408][detail][EM] Flushed pending ack for MessageCounter:70711553 on exchange 50632i
[00:00:00.000][silabs ]==================================================
[00:00:00.000][silabs ]Arduino Matter device starting
[00:00:00.000][silabs ]==================================================
[00:00:00.000][silabs ]Init CHIP Stack
[00:00:00.000][silabs ]Initializing OpenThread stack

[lboue]

Is there an IPv6 packet size limitation in your implementation that would explain these errors?

Line  361: [00:03:50.129][error ][SVR] Server initialization complete
Line  424: [00:03:51.929][error ][BLE] no endpoint for unsub recvd
Line  974: [00:04:21.632][error ][DL] _WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
Line  975: [00:04:21.632][error ][DMG] Error retrieving data from clusterId: 0x0000_0035, err = b
Line 1003: [00:04:21.983][error ][DL] _WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
Line 1004: [00:04:21.984][error ][DMG] Error retrieving data from clusterId: 0x0000_0035, err = b

Fail

Line  939: [00:04:20.991][detail][DMG] <RE:Run> first cluster event is too big so that it fails to fit in the packet!
Line  974: [00:04:21.632][error ][DL] _WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
Line  977: [00:04:21.633][detail][DMG] <RE:Run> first cluster event is too big so that it fails to fit in the [00:04:21.951][detail][IN] UDP Message Received packet nb : 73 SrcAddr : fd4f:21ef:e564:0:83d0:2d1d:5d3f:c9b9[58997] DestAddr : fd4f:21ef:e564:0:b684:b5e0:3915:7a0a[5540] Payload Length 42
Line 1003: [00:04:21.983][error ][DL] _WriteThreadNetworkDiagnosticAttributeToTlv failed: Error CHIP:0x0000000B
Line 1005: [00:04:21.984[00:04:21.984][detail][DMG] <RE:Run> first cluster event is too big so that it fails to fit in the packet!
Line 1050: [00:04:23.044][detail][DMG] <RE:Run> first cluster event is too big so that it fails to fit in the packet!

[lboue]

To compare, I build a Matter light bulb with SimplicityStudio from the SparkFun Thing Plus Matter - MGM240P Hookup Guide.

It works fine with the same board:

Line 1833: [00:03:53.857][info  ][ZCL] Toggle ep1 on/off from state 0 to 1
Line 1838: [00:03:53.857][info  ][ZCL] On/Toggle Command - Stop Timer
Line 1901: [00:03:56.082][info  ][ZCL] Toggle ep1 on/off from state 1 to 0
Line 1940: [00:03:57.599][info  ][ZCL] Toggle ep1 on/off from state 0 to 1
Line 1945: [00:03:57.600][info  ][ZCL] On/Toggle Command - Stop Timer
Line 1991: [00:03:58.814][info  ][ZCL] Toggle ep1 on/off from state 1 to 0
Line 2029: [00:04:36.412][info  ][ZCL] Toggle ep1 on/off from state 0 to 1
Line 2034: [00:04:36.413][info  ][ZCL] On/Toggle Command - Stop Timer

matter_SimplicityStudio_lightbulb_JRTT.log

[lboue]

Did you find the issue root cause?

[lboue]

Since the new release is delayed by a month, could you help me correct this issue?

[silabs-bozont]

This issue will most probably improved on in the next release, but a total fix won't be possible on the current version. Discovery time not only depends on the device, but the Matter hub as well. You could try "stimulating" your device from the app by clicking on it a few times or closing/opening the app. This workaround usually pushes the hub to discover the device quicker - you can see something happening in the RTT logs - sometimes I use this too, but YMMV.
However for me the devices were always discovered right after pairing - the delay only occurred on subsequent reboots.

[lboue]

So why does it work well for examples built with Simplicity Studio?
I only have this delay issue when I build with this Arduino library.
I tried with 3 boards (2 Sparkfun and 1 SiliconLabs xG24-EK2703A) and I got the same issue.
Stimulating doesn't work. I already tried.