Detected blocking call to open inside the event loop by custom integration 'solcast_solar'

Gunth commented 4 months ago

The problem

Since the latest update of HA lot of warnings on startup saying "Detected blocking call to open inside the event loop".

What version of Solcast Integration has the issue?

v4.0.23

What version of Home Assistant are you using?

2024.6.0

Diagnostics information

No response

Logs debug/info/error output

Detected blocking call to open inside the event loop by custom integration 'solcast_solar' at custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f: (offender: /config/custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f:), please create a bug report at https://github.com/oziee/ha-solcast-solar/issues Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/core.py", line 2741, in async_call response_data = await coro File "/usr/src/homeassistant/homeassistant/core.py", line 2784, in _execute_service return await target(service_call) File "/config/custom_components/solcast_solar/__init__.py", line 138, in handle_service_update_forecast await coordinator.service_event_update() File "/config/custom_components/solcast_solar/coordinator.py", line 67, in service_event_update await self.solcast.http_data(dopast=False) File "/config/custom_components/solcast_solar/solcastapi.py", line 554, in http_data await self.serialize_data() File "/config/custom_components/solcast_solar/solcastapi.py", line 97, in serialize_data with open(self._filename, "w") as f:

Additional information

This is not the only custom integration impacted in my list custom one's, here is the same issue for another one and it can be related to this change of ha : https://developers.home-assistant.io/blog/2024/05/19/fix_zoneinfo_blocking_io/

https://github.com/custom-components/nordpool/issues/382

ma9mwah commented 4 months ago

I believe it might be this bit of code that needs to be updated

to "dt_util.async_get_time_zone is now available to replace dt_util.get_time_zone to fetch a time zone in the event loop which is async safe and will not do blocking I/O in the event loop."

I dont have a dev machine to test it out though

onetoomany commented 4 months ago

I tweaked the code directly on my HA instance - and this change works.

michbeck100 commented 4 months ago

@onetoomany Will you create a PR for this?

changeofaspect commented 4 months ago

I tweaked the code directly on my HA instance - and this change works.

Interesting. It didn't work on my install. I replaced 'dt_util.get_time_zone' with 'dt_util.async_get_time_zone' but it broke it, all my Solcast sensors became unavailable and I got a whole load of error messages:

This error originated from a custom integration.

Logger: custom_components.solcast_solar.sensor
Source: custom_components/solcast_solar/sensor.py:325
integration: Solcast PV Forecast (documentation, issues)
First occurred: 13:13:46 (14 occurrences)
Last logged: 13:14:00

SOLCAST - unable to get sensor value tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 321, in extra_state_attributes return self.coordinator.get_sensor_extra_attributes( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 146, in get_sensor_extra_attributes return self.solcast.get_forecast_day(2) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 356, in get_forecast_day da = dt.now(tz).date() + timedelta(days=futureday) ^^^^^^^^^^ TypeError: tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine'
SOLCAST - unable to get sensor value tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 321, in extra_state_attributes return self.coordinator.get_sensor_extra_attributes( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 148, in get_sensor_extra_attributes return self.solcast.get_forecast_day(3) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 356, in get_forecast_day da = dt.now(tz).date() + timedelta(days=futureday) ^^^^^^^^^^ TypeError: tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine'
SOLCAST - unable to get sensor value tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 321, in extra_state_attributes return self.coordinator.get_sensor_extra_attributes( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 150, in get_sensor_extra_attributes return self.solcast.get_forecast_day(4) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 356, in get_forecast_day da = dt.now(tz).date() + timedelta(days=futureday) ^^^^^^^^^^ TypeError: tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine'
SOLCAST - unable to get sensor value tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 321, in extra_state_attributes return self.coordinator.get_sensor_extra_attributes( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 152, in get_sensor_extra_attributes return self.solcast.get_forecast_day(5) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 356, in get_forecast_day da = dt.now(tz).date() + timedelta(days=futureday) ^^^^^^^^^^ TypeError: tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine'
SOLCAST - unable to get sensor value tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine' Traceback (most recent call last): File "/config/custom_components/solcast_solar/sensor.py", line 321, in extra_state_attributes return self.coordinator.get_sensor_extra_attributes( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/coordinator.py", line 154, in get_sensor_extra_attributes return self.solcast.get_forecast_day(6) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/solcast_solar/solcastapi.py", line 356, in get_forecast_day da = dt.now(tz).date() + timedelta(days=futureday) ^^^^^^^^^^ TypeError: tzinfo argument must be None or of a tzinfo subclass, not type 'coroutine'

I reverted back to dt_util.get_timezone and all the Solcast sensors are working again but with the 'Blocking....'_ warning.

HA Core version 2024.6.0 and Solcast version 4.0.23. I wonder what is different?

dbiczo commented 3 months ago

This works on my 2024.6.1 setup for line 94 of custom_components/solcast_solar/__init__.py: await dt_util.async_get_time_zone(str(hass.config.time_zone)),

changeofaspect commented 3 months ago

This works on my 2024.6.1 setup for line 94 of custom_components/solcast_solar/__init__.py: await dt_util.async_get_time_zone(str(hass.config.time_zone)),

Many thanks. I have just tried _await dt_util.async_get_time_zone(str(hass.config.timezone)), and it doesn't break it. However, when I poll the server, I get the original warning message appear:-

Logger: homeassistant.util.loop
Source: util/loop.py:84
First occurred: 15:12:25 (1 occurrences)
Last logged: 15:12:25

Detected blocking call to open inside the event loop by custom integration 'solcast_solar' at custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f: (offender: /config/custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f:), please create a bug report at https://github.com/BJReplay/ha-solcast-solar/issues Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/core.py", line 2741, in async_call response_data = await coro File "/usr/src/homeassistant/homeassistant/core.py", line 2784, in _execute_service return await target(service_call) File "/config/custom_components/solcast_solar/__init__.py", line 140, in handle_service_update_forecast await coordinator.service_event_update() File "/config/custom_components/solcast_solar/coordinator.py", line 67, in service_event_update await self.solcast.http_data(dopast=False) File "/config/custom_components/solcast_solar/solcastapi.py", line 543, in http_data await self.serialize_data() File "/config/custom_components/solcast_solar/solcastapi.py", line 97, in serialize_data with open(self._filename, "w") as f:

So it hasn't fixed the original problem on my system. Now also on 2024.6.1 having updated earlier today.

chrizzzp commented 3 months ago

await dt_util.async_get_time_zone(str(hass.config.time_zone)),

Works also for me again with HA core 2024.6.1.

nicopret1 commented 3 months ago

await dt_util.async_get_time_zone(str(hass.config.time_zone)),

I get the same as @changeofaspect. I replaced line 94 in custom_components/solcast_solar/init.py with: "await dt_util.async_get_time_zone(str(hass.config.time_zone)),"

I'm on HA core 2024.6.1. However, when I reloaded the integration after I made the change I still noticed the error in the log: Detected blocking call to open inside the event loop by custom integration 'solcast_solar' at custom_components/solcast_solar/solcastapi.py, line 230: with open(self._filename) as data_file: (offender: /config/custom_components/solcast_solar/solcastapi.py, line 230: with open(self._filename) as data_file:), please create a bug report at https://github.com/BJReplay/ha-solcast-solar/issues Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 742, in async_setup_locked await self.async_setup(hass, integration=integration) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 594, in async_setup result = await component.async_setup_entry(hass, self) File "/config/custom_components/solcast_solar/__init__.py", line 109, in async_setup_entry await solcast.load_saved_data() File "/config/custom_components/solcast_solar/solcastapi.py", line 230, in load_saved_data with open(self._filename) as data_file:

dbiczo commented 3 months ago

@nicopret1 & @changeofaspect did you restart HA after making the change?

changeofaspect commented 3 months ago

@nicopret1 & @changeofaspect did you restart HA after making the change?

YES. I tried HA Restart and also a complete system reboot. It didn't fix the issue.

At start up I get this warning message which points to line 230 of solcastapi.py. I only seem to get this message once, at start up.

Detected blocking call to open inside the event loop by custom integration 'solcast_solar' at custom_components/solcast_solar/solcastapi.py, line 230: with open(self._filename) as data_file: (offender: /config/custom_components/solcast_solar/solcastapi.py, line 230: with open(self._filename) as data_file:), please create a bug report at https://github.com/BJReplay/ha-solcast-solar/issues Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 742, in async_setup_locked await self.async_setup(hass, integration=integration) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 594, in async_setup result = await component.async_setup_entry(hass, self) File "/config/custom_components/solcast_solar/__init__.py", line 110, in async_setup_entry await solcast.load_saved_data() File "/config/custom_components/solcast_solar/solcastapi.py", line 230, in load_saved_data with open(self._filename) as data_file:

When polling the Solcast server I get this warning message which points to line 97 of solcastapi.py I get this message every time that I poll the server. I don't poll the server at start up, I do it based on a timer running for a random period of time.

Detected blocking call to open inside the event loop by custom integration 'solcast_solar' at custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f: (offender: /config/custom_components/solcast_solar/solcastapi.py, line 97: with open(self._filename, "w") as f:), please create a bug report at https://github.com/BJReplay/ha-solcast-solar/issues Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/core.py", line 2741, in async_call response_data = await coro File "/usr/src/homeassistant/homeassistant/core.py", line 2784, in _execute_service return await target(service_call) File "/config/custom_components/solcast_solar/__init__.py", line 140, in handle_service_update_forecast await coordinator.service_event_update() File "/config/custom_components/solcast_solar/coordinator.py", line 67, in service_event_update await self.solcast.http_data(dopast=False) File "/config/custom_components/solcast_solar/solcastapi.py", line 543, in http_data await self.serialize_data() File "/config/custom_components/solcast_solar/solcastapi.py", line 97, in serialize_data with open(self._filename, "w") as f:

nicopret1 commented 3 months ago

@nicopret1 & @changeofaspect did you restart HA after making the change?

Yes, I performed a restart. I see the same error in the log as @changeofaspect when the following automation runs:

`alias: Solcast update description: "" trigger:

platform: time at: "04:00:00"
platform: time at: "06:00:00"
platform: time at: "08:00:00"
platform: time at: "10:00:00"
platform: time at: "12:00:00"
platform: time at: "14:00:00"
platform: time at: "16:00:00"
platform: time at: "18:00:00"
platform: time at: "20:00:00" condition: [] action:
delay: seconds: "{{ range(30, 360)|random|int }}"
service: solcast_solar.update_forecasts data: {} mode: single`

autoSteve commented 3 months ago

Try https://github.com/BJReplay/ha-solcast-solar/pull/21 @nicopret1.

Restart of HA is required after editing solcastapi.py locally.

changeofaspect commented 3 months ago

Try #21 @nicopret1.

Restart of HA is required after editing solcastapi.py locally.

I have given this a try but the integration does not load. I think I have spotted a mistake on line 664.

line 664

I don't know but I am guessing it should be it be async with aiofiles.open(apiCacheFileName) as f: ?

I tried adding the missing async and the integration now loads. The original warning messages no longer appear but I get a different message so it's close but something else needs looking at.

This error originated from a custom integration.

Logger: py.warnings
Source: custom_components/solcast_solar/solcastapi.py:100
integration: Solcast PV Forecast (documentation, issues)
First occurred: 16:49:38 (1 occurrences)
Last logged: 16:49:38

/usr/local/lib/python3.12/json/__init__.py:180: RuntimeWarning: coroutine '_make_delegate_method.<locals>.method' was never awaited fp.write(chunk)

autoSteve commented 3 months ago

Yeah, needs more thinking about, @changeofaspect & @nicopret1. It blew up on me this morning in the same way. The file reads are NQR.

autoSteve commented 3 months ago

@changeofaspect, @nicopret1

Commit https://github.com/autoSteve/ha-solcast-solar/commit/856f8bc7cf92754e33f66d6fed645e6a70f0837a fixes line 644 to be async. File writes were also very NQR, so it also switches to using an awaited f.write(json.dumps(...)) for file writes, as json.dump(...) using aiofiles was resulting in writing a zero length file to the api cache /config/solcast.json, which I had to restore from backup.

dbiczo commented 3 months ago

After making all changes no more blocking while updating. Thanks

sh00t2kill commented 3 months ago

I just created a PR which i think addresses this -- its been working on my instance for a few days.

nicopret1 commented 3 months ago

Try #21 @nicopret1. Restart of HA is required after editing solcastapi.py locally.

I have given this a try but the integration does not load. I think I have spotted a mistake on line 664.

I don't know but I am guessing it should be it be async with aiofiles.open(apiCacheFileName) as f: ?

I tried adding the missing async and the integration now loads. The original warning messages no longer appear but I get a different message so it's close but something else needs looking at.
This error originated from a custom integration.

Logger: py.warnings
Source: custom_components/solcast_solar/solcastapi.py:100
integration: Solcast PV Forecast (documentation, issues)
First occurred: 16:49:38 (1 occurrences)
Last logged: 16:49:38

/usr/local/lib/python3.12/json/__init__.py:180: RuntimeWarning: coroutine '_make_delegate_method.<locals>.method' was never awaited fp.write(chunk)

Thank you @changeofaspect and @autoSteve https://github.com/BJReplay/ha-solcast-solar/pull/21 fixed the problem. I have no more errors after a restart.

changeofaspect commented 3 months ago

@autoSteve https://github.com/BJReplay/ha-solcast-solar/pull/21 I have made all the required changes and after restarting, it is all working correctly with no error or warning messages at start up or when polling the Solcast server. Also added the changes in https://github.com/BJReplay/ha-solcast-solar/pull/25 which seem to work on my set up. Many thanks for your work on this.

autoSteve commented 3 months ago

A pleasure, @changeofaspect, and a necessity given I run this code 😂. You're 2024.6.0 +-ish, so would be great to have confirmation from someone on < 2024.6.0 (aside from me down-reving my code for the day).

Anyone? (Edit: good luck to me finding someone. The warning does not appear < 2024.6.0 so why seek help?...)

BJReplay commented 3 months ago

Fixed in https://github.com/BJReplay/ha-solcast-solar/pull/25

michbeck100 commented 3 months ago

@BJReplay are you going to release this bugfix soon?

nicopret1 commented 3 months ago

A pleasure, @changeofaspect, and a necessity given I run this code 😂. You're 2024.6.0 +-ish, so would be great to have confirmation from someone on < 2024.6.0 (aside from me down-reving my code for the day).

Anyone? (Edit: good luck to me finding someone. The warning does not appear < 2024.6.0 so why seek help?...)

Many thanks @autoSteve. I tested on both 2024.6.1 and 2024.6.2 and didn't see any issues

BJReplay / ha-solcast-solar