Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CommandSender.cpp:343: CHIP Error 0x00000032: Timeout in Matter add-on #3900

Open
agners opened this issue Jan 20, 2025 · 4 comments
Open

CommandSender.cpp:343: CHIP Error 0x00000032: Timeout in Matter add-on #3900

agners opened this issue Jan 20, 2025 · 4 comments

Comments

@agners
Copy link
Member

agners commented Jan 20, 2025

Thank you @agners for looking into our cases.

In HA core logs, I see many timeout failures when turning my lights on or off. I usually have to toggle multiple times to completely turn on / off all the lights of the light groups.

Logger: homeassistant.components.automation.living_room_lights_turn_on
Quelle: components/automation/__init__.py:718
Integration: Automation (Dokumentation, Probleme)
Erstmals aufgetreten: 16:15:56 (1 Vorkommnisse)
Zuletzt protokolliert: 16:15:56

While executing automation automation.living_room_lights_turn_on
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 718, in async_trigger
    return await self.action_script.async_run(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        variables, trigger_context, started_action
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1801, in async_run
    return await asyncio.shield(create_eager_task(run.async_run()))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 464, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 528, in _async_step
    self._handle_exception(
    ~~~~~~~~~~~~~~~~~~~~~~^
        ex, continue_on_error, self._log_exceptions or log_exceptions
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 558, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 526, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 764, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 727, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2795, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2838, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1031, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1628, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1078, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 644, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/group/light.py", line 179, in async_turn_on
    await self.hass.services.async_call(
    ...<5 lines>...
    )
  File "/usr/src/homeassistant/homeassistant/core.py", line 2795, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2838, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1031, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1628, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1078, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 644, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/matter/light.py", line 319, in async_turn_on
    await self.send_device_command(
        clusters.OnOff.Commands.On(),
    )
  File "/usr/src/homeassistant/homeassistant/components/matter/light.py", line 287, in send_device_command
    await self.matter_client.send_device_command(
    ...<3 lines>...
    )
  File "/usr/local/lib/python3.13/site-packages/matter_server/client/client.py", line 460, in send_device_command
    return await self.send_command(
           ^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/matter_server/client/client.py", line 589, in send_command
    return await future
           ^^^^^^^^^^^^
matter_server.common.errors.UnknownError: src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout

I also attach another Matter Server add-on log in case it helps: matter_server_log.txt

In the OTBR add-on log, I see many lines of
00:23:37.086 [W] P-RadioSpinel-: Handle transmit done failed: ChannelAccessFailure

Could that be related to the original cause?

Originally posted by @ChristianForstner in #3889
@agners agners mentioned this issue Jan 20, 2025
Open
@agners
Copy link
Member Author

agners commented Jan 20, 2025 

matter_server.common.errors.UnknownError: src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout

...this...

In the OTBR add-on log, I see many lines of
00:23:37.086 [W] P-RadioSpinel-: Handle transmit done failed: ChannelAccessFailure

together with this usually means that there is a radio (RF) level problem. ChannelAccessFailure means that the OTBR was not able to deliver a message because there was ongoing traffic on the channel over a longer period of time. Make sure that your WiFi and Thread network don't use overlapping channels, and make sure that your Thread radio is not suffering from interference of other devices (e.g. USB 3.0 devices are known to interfere).

@ChristianForstner
Copy link

ChristianForstner commented Jan 22, 2025 •
edited
Loading

Thanks for your suggestions and moving my specific problem to this newly opened issue.

I checked the WiFi settings and set the 2.4 GHz band now to a fixed channel 6. The Thread network is per default on Yellow on channel 15.
There are no device connected to the HA Yellow board except the CM4 and a 1 TB 970 Evo Plus by Samsung (as recommended by the FAQ). I'm unsure if the PCIe link to the NVMe drive could lead to that much interference.

After changing the agent log level on the OTBR add-on to notice, I got the logs below. Therefore, I think, my issue could be similar to 3582 although the Matter Server add-on error is different in this comment

19:34:59.437 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
19:34:59.437 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1243, chksum:a418, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.375, radio:15.4
19:34:59.437 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:208d:fad6:f1be:3814]:5540
19:34:59.437 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
23:01:29.899 [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:96, chksum:2d82, ecn:no, to:e69672345704be04, sec:no, error:NoAck, prio:net, radio:15.4
23:01:29.899 [N] MeshForwarder-:     src:[fe80:0:0:0:4083:16da:41cc:bc]:19788
23:01:29.899 [N] MeshForwarder-:     dst:[fe80:0:0:0:e496:7234:5704:be04]:19788
23:03:32.732 [W] Nat64---------: no mapping found for the IPv4 address
23:03:32.784 [W] Nat64---------: no mapping found for the IPv4 address
23:04:06.804 [W] Nat64---------: no mapping found for the IPv4 address
23:04:06.868 [W] Nat64---------: no mapping found for the IPv4 address
23:59:27.681 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:112, dglen:1243
23:59:27.693 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:200, dglen:1243
23:59:27.706 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:288, dglen:1243
23:59:27.729 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:376, dglen:1243
23:59:27.736 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:464, dglen:1243
23:59:27.750 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:552, dglen:1243
23:59:27.763 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:640, dglen:1243
23:59:27.777 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:728, dglen:1243
23:59:27.788 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:816, dglen:1243
23:59:27.795 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:904, dglen:1243
23:59:27.801 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x2400, dst:0x7000, sec:yes, tag:12392, offset:112, dglen:1235
23:59:27.808 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55559, offset:992, dglen:1243
23:59:27.814 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x2400, dst:0x7000, sec:yes, tag:12392, offset:464, dglen:1235
23:59:27.843 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x2400, dst:0x7000, sec:yes, tag:12392, offset:552, dglen:1235
23:59:27.855 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x2400, dst:0x7000, sec:yes, tag:12392, offset:728, dglen:1235
23:59:27.861 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:200, dglen:1243
23:59:27.868 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:376, dglen:1243
23:59:27.884 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x2400, dst:0x7000, sec:yes, tag:12392, offset:904, dglen:1235
23:59:27.898 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:816, dglen:1243
23:59:27.938 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:904, dglen:1243
23:59:28.078 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:992, dglen:1243
23:59:28.089 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:1080, dglen:1243
23:59:28.094 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:75, src:0x7400, dst:0x7000, sec:yes, tag:55560, offset:1168, dglen:1243
23:59:29.840 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1235, chksum:0c85, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.0, radio:15.4
23:59:29.840 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:d049:a399:dd9c:d374]:5540
23:59:29.840 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
23:59:29.840 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1243, chksum:129a, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.0, radio:15.4
23:59:29.840 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:36b2:c4f:5b4e:d035]:5540
23:59:29.840 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
23:59:30.320 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:75, src:0x7400, dst:0x7000, sec:yes, tag:55565, offset:1168, dglen:1243
23:59:32.847 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1048, chksum:ec93, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.125, radio:15.4
23:59:32.847 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:d049:a399:dd9c:d374]:5540
23:59:32.847 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
23:59:32.847 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1243, chksum:129a, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.125, radio:15.4
23:59:32.847 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:36b2:c4f:5b4e:d035]:5540
23:59:32.847 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
1d.00:00:11.108 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:65, src:0x2400, dst:0x7000, sec:yes, tag:12407, offset:1168, dglen:1233
1d.00:00:11.152 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x0000, dst:0x7000, sec:yes, tag:18114, offset:816, dglen:1243
1d.00:00:11.158 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x0000, dst:0x7000, sec:yes, tag:18114, offset:904, dglen:1243
1d.00:00:11.164 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x0000, dst:0x7000, sec:yes, tag:18114, offset:992, dglen:1243
1d.00:00:11.189 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:88, src:0x0000, dst:0x7000, sec:yes, tag:18114, offset:1080, dglen:1243
1d.00:00:11.200 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:75, src:0x0000, dst:0x7000, sec:yes, tag:18114, offset:1168, dglen:1243
1d.00:00:13.854 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1233, chksum:c961, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.0, radio:15.4
1d.00:00:13.854 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:eb5a:8178:4eef:f205]:5540
1d.00:00:13.854 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
1d.00:00:13.854 [N] MeshForwarder-: Dropping (reassembly queue) IPv6 UDP msg, len:1243, chksum:cd71, ecn:no, sec:yes, error:ReassemblyTimeout, prio:normal, rss:-87.0, radio:15.4
1d.00:00:13.854 [N] MeshForwarder-:     src:[fdf2:ef18:a99b:1:d9a2:f2e8:5588:3720]:5540
1d.00:00:13.854 [N] MeshForwarder-:     dst:[fdf2:ef18:a99b:1:2dd7:90e8:8e20:23a6]:44295
1d.00:03:31.810 [W] Nat64---------: no mapping found for the IPv4 address
1d.00:03:32.591 [W] Nat64---------: no mapping found for the IPv4 address
1d.00:04:27.275 [W] Nat64---------: no mapping found for the IPv4 address
1d.00:04:28.079 [W] Nat64---------: no mapping found for the IPv4 address
1d.00:30:03.308 [N] Ip6-----------: Bad UDP checksum
1d.00:30:03.308 [W] Ip6-----------: Failed to handle payload: Drop
1d.00:30:03.308 [W] Ip6-----------: Failed to handle payload: Drop

@ChristianForstner
Copy link

I think, I identified the two main reasons for the issues I'm facing. I've been using Nanoleaf Sense+ Control light switches with firmware version 4.0.0 and exposed two buttons of each switch to HA by using the switches' Matter beta feature. The main purpose of the exposed buttons was to control light groups. As soon as one of the buttons were pressed e.g. to toggle light groups, all Matter devices became completely unresponsive for several minutes and the logs were flooded as observed above. After replacing these light switches by Aqara H2 EU ones, the situation improved a lot. Nevertheless, toggling light groups with more than ~10 devices still results in stuttering and hanging devices. By reducing the group sizes below 10, all issues are gone.

As of now, I would not recommend anyone to use the Nanoleaf Sense+ Control's Matter beta feature with the current firmware version. What's however not so clear to me is why groups with a reasonable number of devices would cause these kind of problems.

@CRK1918
Copy link

CRK1918 commented Feb 22, 2025

I had about 10 Matter devices, 9 other devices( Bulbs ) control are OK,

I have same error with 1 devices (bulb) and the delay was very slow, it is about 30 seconds to a minute:

src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout

Image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@agners @CRK1918 @ChristianForstner