Shelly: aioshelly (Concurrent call to receive() is not allowed")

martinarva commented 7 months ago

The problem

Shelly integration has crached my HA since yesterday. I guess it's related to 2023.12 update which happened also yesterday. Happened once yesterday and now this morning again. Had to restart the HA docker to be able to access HA UI again.

HA just hangs and UI is not available. Last log items are these (like 10 of them):

File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive raise RuntimeError("Concurrent call to receive() is not allowed") RuntimeError: Concurrent call to receive() is not allowed 2023-12-08 07:12:48.593 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 755 2023-12-08 07:12:48.593 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive()

What version of Home Assistant Core has the issue?

core-2023.12.0

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

Shelly

Link to integration documentation on our website

https://www.home-assistant.io/integrations/shelly/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 7 months ago

Hey there @balloob, @bieniu, @thecode, @chemelli74, @bdraco, mind taking a look at this issue as it has been labeled with an integration (shelly) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `shelly` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign shelly` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

shelly documentation shelly source _{^{(message by IssueLinks)}}

chemelli74 commented 7 months ago

Hi, could you please post:

Information screen of your HA installation
diagnostic of the device
full debug log

branbon commented 7 months ago

I also am experiencing this, and it also causes enough log-spam that my home-assistant client becomes unresponsive & over the span of ~18 hours or so has logged ~60GB worth of those repeating messages. I also was not experiencing this prior to 2023.12. I am running via Docker on a Radxa Rock 5 Model B.

I can try to provide additional details if needed:

2023-12-09 18:52:55.529 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.1.220: Pong not received, device is likely unresponsive; disconnecting
2023-12-09 18:53:33.040 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2023-12-09 18:53:33.047 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 231
2023-12-09 18:53:33.050 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed

I have also enabled debug logging on the integration and will report any additional details that might show up there.

thecode commented 7 months ago

I have suspect it is related to https://github.com/home-assistant-libs/aioshelly/pull/426 becasue it has a slight change how we handle futures, @bdraco what do you think?

chemelli74 commented 7 months ago

@brandond please share all the requested information

branbon commented 7 months ago

Information screen of your HA installation (pulled via settings -> system -> repairs, 3-dot menu in corner)

System Information

version	core-2023.12.1
installation_type	Home Assistant Container
dev	false
hassio	false
docker	true
user	root
virtualenv	false
python_version	3.11.6
os_name	Linux
os_version	5.10.160-legacy-rk35xx
arch	aarch64
timezone	America/New_York
config_dir	/config

Home Assistant Cloud

Dashboards

Recorder

diagnostic of the device (sensitive info removed) diagnostics-shelly-plugus-data-device-with-issue.txt
full debug log (15min leading up to event, sensitive info removed) shelly-logs.log

@chemelli74 I assume you meant to tag me, and I was waiting until I was able to trigger the issue with debug logging enabled as the issue is sporadic and tends to only happen at night when I am asleep.

brandond commented 7 months ago

Wrong @ there, I don't think you wanted me.

stuckinger commented 7 months ago

Same Here. I could got it working again with a rebuild of the container after the upgrade. I do not know which docker version was running before upgrade. After rebuild the high load and log flooding is gone! Shelly integration also works.

Current HA info:

System Information

version	core-2023.12.1
installation_type	Home Assistant Container
dev	false
hassio	false
docker	true
user	root
virtualenv	false
python_version	3.11.6
os_name	Linux
os_version	6.1.0-15-amd64
arch	x86_64
timezone	Europe/Berlin
config_dir	/config

Home Assistant Cloud

Dashboards

Recorder

Maybe it helps?

martinarva commented 7 months ago

Same Here. I could got it working again with a rebuild of the container after the upgrade. I do not know which docker version was running before upgrade. After rebuild the high load and log flooding is gone! Shelly integration also works.

Current HA info:

System Information

version core-2023.12.1 installation_type Home Assistant Container dev false hassio false docker true user root virtualenv false python_version 3.11.6 os_name Linux os_version 6.1.0-15-amd64 arch x86_64 timezone Europe/Berlin config_dir /config Home Assistant Cloud logged_in false can_reach_cert_server ok can_reach_cloud_auth ok can_reach_cloud ok Dashboards dashboards 12 resources 1 views 14 mode storage Recorder oldest_recorder_run 2. Dezember 2023 um 21:38 current_recorder_run 12. Dezember 2023 um 07:31 estimated_db_size 986.74 MiB database_engine sqlite database_version 3.41.2 Maybe it helps?

Did the same. At the moment looks stable

christofnolden commented 7 months ago

Same here... Spammed the log file until the disk was full...

File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive raise RuntimeError("Concurrent call to receive() is not allowed") RuntimeError: Concurrent call to receive() is not allowed 2023-12-12 03:39:52.414 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 13 2023-12-12 03:39:52.414 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^

EDIT: The recreation / rebuilt of the container fixed the problem.

branbon commented 7 months ago

Since encountering this last, I have:

power cycled the device
updated to the latest beta firmware on my shelly plug
relocated the device causing the issue to be closer to the nearest wireless access point
updated to the latest home-assistant container version (2023.12.3)

Since doing all that, the container has been up and running without having this issue thrown. I believe I encountered it today (home-assistant became unresponsive & CPU usage became pinned to 15%-20%), but have also added this to my configuration.yaml to avoid running out of disk space (so will no longer see the main error logs I included previously):

logger:
  default: warning
  filters:
    # filter for aioshelly.rpc_device.wsrpc errors
    aioshelly.rpc_device.wsrpc:
      - "^Unexpected error while receiving message.*$"
      - "^Response for an unknown request id.*$"

oxigen-dev commented 7 months ago

Same happened to me, today for the 2nd time ever (1st time was some days ago). With restarting the docker container I can get back to the UI.

mf76130 commented 7 months ago

had the same, then i saw 1 dead shelly device in my shelly setup (not in home assistant), deleted that one from the shelly app and since that time silence.

mxilievski commented 7 months ago

This one is bugging me out for the past one week. Last time occurred when my network equipment started to update at 3 AM, dropping around 20 Shelly devices out for about 10 minutes.

chemelli74 commented 7 months ago

@all, which other devices you have, if any, in your HA installation that doesn't suffer this issue ?

mxilievski commented 7 months ago

@ALL, which other devices you have, if any, in your HA installation that doesn't suffer this issue ?

I have a mix of Shelly 1PM, 2PM, 1 Plus, RGBW2, 2.5.

Looking at the logs, there is nothing obvious about the device that is causing it.

The rest of the log is the just the error repeating itself.

Update: If by any chance this error is related

This error is only coming from 2PM, 1 Plus, 1PM devices Gen2. Gen1 devices are not throwing the error above.

oxigen-dev commented 7 months ago

@ALL, which other devices you have, if any, in your HA installation that doesn't suffer this issue ?

I have:

Shelly Plug S x4
Shelly Plus 2PM x1
Shelly Plus 1 x3
Shelly Door/Window 2 x1
Shelly RGBW2 x2

I'm also not sure which is causing the issue.

chemelli74 commented 7 months ago

Sorry, I reword the question that was not clear enough: what other brand devices a part from Shelly you have in your HA environment ?

bieniu commented 7 months ago

Error seems to be related to websocket https://github.com/aio-libs/aiohttp/issues/999 so I think it's only affects gen2 devices.

Please provide the following information:

HA installation type
Shelly Plus/Pro device firmware version

If Pro/Plus devices are using beta firmware, please roll back to the stable version and re-test HA stability.

mxilievski commented 7 months ago

Error seems to be related to websocket aio-libs/aiohttp#999 so I think it's only affects gen2 devices.

Please provide the following information:

HA installation type

Shelly Plus/Pro device firmware version

If Pro/Plus devices are using beta firmware, please roll back to the stable version and re-test HA stability.

HA installation type: Docker, latest image 2023.12.3

Shelly Plus/Pro device firmware version: All 2gen devices are on their latest stable firmware 20231106-160328/1.0.8-gdba0ee3

ruimarinho commented 7 months ago

I am also experiencing this problem randomly. CPU usage skyrockets due to log spam. Anything I can do to help troubleshoot this? I am running a mixed environment with Shelly Gen1 and Gen2.

oxigen-dev commented 7 months ago

Error seems to be related to websocket aio-libs/aiohttp#999 so I think it's only affects gen2 devices.

Please provide the following information:
* HA installation type

* Shelly Plus/Pro device firmware version
If Pro/Plus devices are using beta firmware, please roll back to the stable version and re-test HA stability.

HA installation type: Docker. All of my Gen2 Shelly devices are on the latest stable firmware: 20231106-160229/1.0.8-gdba0ee3 and 20231106-160328/1.0.8-gdba0ee3.

bieniu commented 7 months ago

Is anyone having these problems using a different type of installation than "Home Assistant Container"?

dannytsang commented 7 months ago

@bieniu mine is a VM install

bieniu commented 7 months ago

@dannytsang Please attach a diagnostic file.

ruimarinho commented 7 months ago

I'm running via the official docker image in host mode.

branbon commented 7 months ago

Here are the logs from my most recent event, (excluding "^Unexpected error while receiving message.*$" & "^Response for an unknown request id.*$" logs that is):

shelly-logs-2.log

All of my shelly devices are just Shelly Plug Plus US. I have just updated all deices to the latest stable 1.1.0 device firmware that was released today, (was running into this on 1.0.8 and was what prompted me to update to 1.1.0-beta* in an attempt to resolve the issue).

dersch81 commented 7 months ago

Hi, i have daily unexpected reboots of HA due to this issue. Started from 2023.12.0 now i'm on 2023.12.3. I'm running HASSOS on Proxmox VM.

I have a lot if Gen2 devices but also Gen1 Shellies. Updated all Gen2 to 1.1.0 today. Except one which has unstable wifi connection. It is still on 1.0.8

That is the last log before the last unexpected reboot

2023-12-21 10:53:22.582 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 1880
2023-12-21 10:53:22.582 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2023-12-21 10:53:22.583 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 1880
2023-12-21 10:53:22.583 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2023-12-21 10:53:22.584 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 1880
2023-12-21 10:53:22.584 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2023-12-21 10:53:22.585 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 1880

Is any information still necessary to find the cause?

dannytsang commented 7 months ago

@dannytsang Please attach a diagnostic file.

I haven't had a chance to capture one. The below is an extract from home-assistant.log.1 file where I noticed the issue. It repeats itself so much the file is ~1.9GB :

2023-12-10 15:34:00.827 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.20.124: Pong not received, device is likely unresponsive; disconnecting
2023-12-10 15:34:02.085 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 616, in state
    numerical_value = int(value)
                      ^^^^^^^^^^
ValueError: invalid literal for int() with base 10: '"0"4'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 619, in state
    numerical_value = float(value)
                      ^^^^^^^^^^^^
ValueError: could not convert string to float: '"0"4'

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/template/coordinator.py", line 92, in _handle_triggered
    self.async_set_updated_data(
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 426, in async_set_updated_data
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/components/template/trigger_entity.py", line 55, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 623, in state
    raise ValueError(
ValueError: Sensor sensor.growatt_grid_export_power has device class 'power', state class 'measurement' unit 'kW' and suggested precision 'None' thus indicating it has a numeric value; however, it has the non-numeric value: '"0"4' (<class 'str'>)
2023-12-10 15:34:03.340 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2023-12-10 15:34:03.341 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed

antsalm commented 7 months ago

Similar issue with the 2023.12 version and onwards. I've rolled back to 2023.11.2 and have not experienced it since, nor crashes of my Homeassistant instant ever before, and it has been pretty unchanged for couple of months.

I'm running Home Assistant on Container with ARM64. Shelly 1PMs with 20231219-133934/1.1.0-g34b5d4f Firmware

What I can observe from the logs: Shelly 2gen (Shelly 1PM) device loses connection, it ends up in some kind of an error loop which eventually crashes the HomeAssistant. Sometimes it is able to recover, if its only one device (maybe?) These Shelly devices appearing on logs are connected with D-LINK WiFi extender which has minor unreliability, but has not caused this kind issues.

Currently trying to test with 2023.12.3, and remeditate situation by improving the WIFI-connection and avoiding disconnects.

2023-12-23 09:13:59.308 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Shelly1pm_2 data: Device disconnected: DeviceConnectionError() v2023-12-23 09:14:09.560 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Shelly1pm_4 data: Device disconnected: DeviceConnectionError() 2023-12-23 09:14:38.346 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Shelly1pm_5 data: Device disconnected: DeviceConnectionError() 2023-12-23 09:14:51.369 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.107.21: Pong not received, device is likely unresponsive; disconnecting 2023-12-23 09:14:58.567 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.107.24: Pong not received, device is likely unresponsive; disconnecting 2023-12-23 09:14:59.460 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.107.23: Pong not received, device is likely unresponsive; disconnecting

Multiple of these errors within one second: 2023-12-23 09:15:00.829 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Shelly1pm_5 data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing

It may continue even if devices are connected back: 2023-12-23 09:15:01.294 INFO (MainThread) [aioshelly.rpc_device.wsrpc] Connected to 192.168.107.24 2023-12-23 09:15:01.309 INFO (MainThread) [aioshelly.rpc_device.wsrpc] Connected to 192.168.107.21 2023-12-23 09:15:01.379 INFO (MainThread) [aioshelly.rpc_device.wsrpc] Connected to 192.168.107.23 2023-12-23 09:15:02.659 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Shelly1pm_2 data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing

Eventually it led to these two messages looping which I believe when HA wents unresponsive. Creating roughly 100mb of log in 10minutes.: 2023-12-23 09:15:32.155 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 1354 2023-12-23 09:15:32.156 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive raise RuntimeError("Concurrent call to receive() is not allowed") RuntimeError: Concurrent call to receive() is not allowed

mf76130 commented 6 months ago

no problems since the 18th and then some devices lost connection and error loop for 6min 31mb log file - reboot of HA. Just adding more logs in case its helpful: 2023-12-26 03:31:57.240 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Kühlschrank Küche data: Error fetching data: DeviceConnectionError() 2023-12-26 03:33:18.387 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Licht Eingang data: Error fetching data: DeviceConnectionError() 2023-12-26 03:33:38.561 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:34:03.387 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Licht Eingang data: Error fetching data: DeviceConnectionError() 2023-12-26 03:34:53.561 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:35:07.408 ERROR (MainThread) [custom_components.roborock.coordinator] Error fetching roborock data: id=11862 Timeout after 4 seconds 2023-12-26 03:35:53.560 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:36:58.387 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Licht Eingang data: Error fetching data: DeviceConnectionError() 2023-12-26 03:37:24.560 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:37:53.719 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] 192.168.0.75: Pong not received, device is likely unresponsive; disconnecting 2023-12-26 03:38:00.530 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Photovoltaik Gartenhaus data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing 2023-12-26 03:38:00.628 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Photovoltaik Gartenhaus data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing 2023-12-26 03:38:00.656 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Photovoltaik Gartenhaus data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing 2023-12-26 03:38:10.528 ERROR (MainThread) [homeassistant.components.shelly] Unexpected error fetching Photovoltaik Gartenhaus data: Already initializing Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 300, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/coordinator.py", line 531, in _async_update_data await self.device.initialize() File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 142, in initialize raise RuntimeError("Already initializing") RuntimeError: Already initializing 2023-12-26 03:38:10.691 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:38:50.435 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Licht Eingang data: Error fetching data: DeviceConnectionError() 2023-12-26 03:39:00.532 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval await self._async_refresh(log_failures=True, scheduled=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 385, in _update_callback self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state state, attr = self._async_generate_attributes() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes state = self._stringify_state(available) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state if (state := self.state) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/binary_sensor/__init__.py", line 227, in state if (is_on := self.is_on) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/binary_sensor.py", line 299, in is_on return bool(self.attribute_value) ^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 533, in attribute_value self.status.get(self.entity_description.sub_key), self._last_value ^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 375, in status return cast(dict, self.coordinator.device.status[self.key]) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 340, in status raise NotInitialized aioshelly.exceptions.NotInitialized 2023-12-26 03:39:00.575 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval await self._async_refresh(log_failures=True, scheduled=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 385, in _update_callback self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state state, attr = self._async_generate_attributes() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes state = self._stringify_state(available) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state if (state := self.state) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/binary_sensor/__init__.py", line 227, in state if (is_on := self.is_on) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/binary_sensor.py", line 299, in is_on return bool(self.attribute_value) ^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 533, in attribute_value self.status.get(self.entity_description.sub_key), self._last_value ^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 375, in status return cast(dict, self.coordinator.device.status[self.key]) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 340, in status raise NotInitialized aioshelly.exceptions.NotInitialized 2023-12-26 03:39:00.630 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval await self._async_refresh(log_failures=True, scheduled=True) File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh self.async_update_listeners() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners update_callback() File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 385, in _update_callback self.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state state, attr = self._async_generate_attributes() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes state = self._stringify_state(available) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state if (state := self.state) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/binary_sensor/__init__.py", line 227, in state if (is_on := self.is_on) is None: ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/binary_sensor.py", line 299, in is_on return bool(self.attribute_value) ^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 533, in attribute_value self.status.get(self.entity_description.sub_key), self._last_value ^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/shelly/entity.py", line 375, in status return cast(dict, self.coordinator.device.status[self.key]) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/device.py", line 340, in status raise NotInitialized aioshelly.exceptions.NotInitialized 2023-12-26 03:39:04.258 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Photovoltaik Gartenhaus data: Device disconnected: DeviceConnectionError(TimeoutError()) 2023-12-26 03:39:10.677 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Steinsteckdose Birke data: Error fetching data: DeviceConnectionError() 2023-12-26 03:39:16.241 ERROR (MainThread) [homeassistant.components.shelly] Error fetching Kühlschrank Küche data: Error fetching data: DeviceConnectionError() 2023-12-26 03:39:20.260 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive raise RuntimeError("Concurrent call to receive() is not allowed") RuntimeError: Concurrent call to receive() is not allowed 2023-12-26 03:39:20.280 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive raise RuntimeError("Concurrent call to receive() is not allowed") RuntimeError: Concurrent call to receive() is not allowed 2023-12-26 03:39:20.292 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs msg = await self._client.receive() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^

cermakjn commented 6 months ago

Hi, I've experienced the same issue. It occurs every time I restart my central router.

I'm using the HA 2023.12 in a container, running on RaspberryPi 4 - Raspbian OS.

Steps to replicate:

HA is ON, router is ON - No problem
HA is ON, router is OFF - No problem
HA is ON, router back ON - Shelly can't connect and I received a so many logs like this one:

2023-12-24 21:14:20.060 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed

Since then, HA is unresponsive and nothing works - possibly due to high CPU load caused by this.

bieniu commented 6 months ago

Please do not attach the same logs over and over again. Diagnostics files would be more helpful.

I could got it working again with a rebuild of the container after the upgrade.

Can anyone confirm this helps in the long term? Have others tried this solution?

branbon commented 6 months ago

I could got it working again with a rebuild of the container after the upgrade.

Can anyone confirm this helps in the long term? Have others tried this solution?

I can confirm it did not help in the long term. Recreating / restarting the container does not address the root issue at all, it is just a temporary 'fix' to reset the container state to one that is not throwing the same exception in a loop indefinitely.

Since adjusting my wifi settings & relocating my problematic device to have a better signal, I have encountered this issue significantly less. (from multiple times a day to only once a week or so). So I would agree with the others indicating that this is most likely caused by some issue from an unexpected network dropout.

dannytsang commented 6 months ago

I too see suspect related to connectivity issue like @brandond because my WiFi is noticeably unreliable during the day (suspect it's interference related but never go to the bottom of this). Here's the uptime kuma events for the past few days. Granted, they are not all related Shelly e.g. 2023.12.4 was upgraded today. Compared to pre 2023.12 which I believe I upgraded to on 2023-12-07:

@bieniu If this is just noise then let me know however this is what my gut is telling me. I tried watching the logs for when it happens to initiate a diagnostics log but kept missing.

LordShadowen commented 6 months ago

Wanted to chime in that I just experienced the same thing - in my case, it was immediately after a full house power failure. Both HASS and the networking equipment are on a UPS, so everything kept running, but the Shelly devices are not. At some point during the loss of communication the same thing happened - HA become unresponsive, gigantic log spam of:

RuntimeError: Concurrent call to receive() is not allowed

and

 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")

bieniu commented 6 months ago

Yesterday I tried for several hours to reproduce this problem on my environments (HAOS and core) and failed. Please attach diagnostic files. This is a blind shot but maybe some custom component is forcing an older version of aiohttp.

mxilievski commented 6 months ago

Yesterday I tried for several hours to reproduce this problem on my environments (HAOS and core) and failed. Please attach diagnostic files. This is a blind shot but maybe some custom component is forcing an older version of aiohttp.

This helps?

bdraco commented 6 months ago

_rx_task isn't cancelled on disconnect it only set to None

bdraco commented 6 months ago

I can't replicate the problem since its likely requires a poor quality connection to trigger the unclean disconnect

https://github.com/home-assistant-libs/aioshelly/pull/473 will probably fix it if someone wants to try it

mf76130 commented 6 months ago

I did following tests this morning:

Turn off the power circuit of the devices that seemed to have caused the error messages for 20min -> no increase on the log
reduce the transmition power of the wifi APs, this causes high latency between 200ms and 900ms, also packet drops for 5s -> no increase on the log

I did now enable debugging on shelly integration, and we have to wait till it fails again

cafsenra commented 6 months ago

Hi I am having this issue with homeassistant running in docker and shelly devices 3 shelly2pm and on shelly H&T Plus. Did anyone managed to solve this issue?

cermakjn commented 6 months ago

Hi,

it happened again, so I enable debug log and here it is. Hope it should help. It started at 2024-01-01 16:16:45.220 - my router has been restarted.

home-assistant.diagnostic.log

I'm using HA in Container and I have several Shelly Plug S, Shelly Plug Plus S and Shelly Flood Sensor.

qbushome commented 6 months ago

I have the exact same problem as described above, also, my logfiles show the same error. I have a lot of unavailable shelly's (because of experimenting a lot). I thought, let's disable all of them. Unfortunately, unpredicted restarts keep happening. I run HA supervised in a proxmox environment. Up to date to 2023.12.4

The first logentry after the restart is always disturbing: The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly 2 januari 2024 om 23:55:10 – (WAARSCHUWING) Recorder

bdraco commented 6 months ago

The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly 2 januari 2024 om 23:55:10 – (WAARSCHUWING) Recorder

When the problem happens it goes into an infinite loop so its likely it can't shutdown properly.

I'm 95% sure https://github.com/home-assistant-libs/aioshelly/pull/473 will fix the issue

chrispontiga commented 6 months ago

I've also experienced this three times in recent weeks. Also using the docker container:

2024-01-05 06:59:08.353 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 821
2024-01-05 06:59:08.354 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2024-01-05 06:59:08.356 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 821
2024-01-05 06:59:08.357 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2024-01-05 06:59:08.359 WARNING (MainThread) [aioshelly.rpc_device.wsrpc] Response for an unknown request id: 821
2024-01-05 06:59:08.360 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed

mtausk commented 6 months ago

Hi,

I have just spotted this error:

File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2024-01-13 20:31:10.192 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()

Core 2024.1.0 (Docker version)

Just to clarify. Is this fixed in 2024.1.3?

Thanks.

dannytsang commented 6 months ago

Hi,

I have just spotted this error:

File "/usr/local/lib/python3.11/site-packages/aiohttp/client_ws.py", line 232, in receive
    raise RuntimeError("Concurrent call to receive() is not allowed")
RuntimeError: Concurrent call to receive() is not allowed
2024-01-13 20:31:10.192 ERROR (MainThread) [aioshelly.rpc_device.wsrpc] Unexpected error while receiving message
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aioshelly/rpc_device/wsrpc.py", line 328, in _rx_msgs
    msg = await self._client.receive()

Core 2024.1.0 (Docker version)

Just to clarify. Is this fixed in 2024.1.3?

Thanks.

The fix was merged into 2024.1.3. I haven't had any issues today but keeping an eye on it.

mf76130 commented 6 months ago

Interesting thing, i don't see these alerts anymore, but my HA now reboots without those errors. Last Log entry is "Chromecast Error reading from socket."

chemelli74 commented 6 months ago

If you have still problems with Shelly, please open a new issue with fresh diagnostics and debug log.

home-assistant / core