mrk-its / homeassistant-blitzortung

Custom Component for fetching lightning data from blitzortung.org
MIT License
186 stars 38 forks source link

non-threadsafe calls #85

Closed Mariusthvdb closed 2 months ago

Mariusthvdb commented 5 months ago
2024-02-27 10:18:03.610 ERROR (SyncWorker_6) [homeassistant.util.logging] Exception in _on_connection_change when dispatching 'blitzortung_mqtt_connected': ()
Traceback (most recent call last):
  File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change
    sensor.async_write_ha_state()

as found while using debugy with BDraco trying to eliminate issues in the HA startup sequence

using 2024.3.0.dev20240227 and Blitzortung 1.3.1

please have a look, thanks

Mariusthvdb commented 4 months ago

adding to the above:

Logger: homeassistant.util.logging
Bron: util/logging.py:102
First occurred: 16:27:42 (1 gebeurtenissen)
Laatst gelogd: 16:27:42

Exception in _on_connection_change when dispatching 'blitzortung_mqtt_connected': () Traceback (most recent call last): File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change sensor.async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 992, in async_write_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1175, in _async_write_ha_state hass.states.async_set( File "/usr/src/homeassistant/homeassistant/core.py", line 1964, in async_set self._bus.async_fire( File "/usr/src/homeassistant/homeassistant/core.py", line 1290, in async_fire self._hass.async_add_hass_job(job, event) File "/usr/src/homeassistant/homeassistant/core.py", line 603, in async_add_hass_job task = self.loop.create_task(hassjob.target(*args), name=hassjob.name) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/asyncio/base_events.py", line 457, in create_task task = tasks.Task(coro, loop=self, name=name, context=context) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/asyncio/base_events.py", line 795, in call_soon self._check_thread() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 832, in _check_thread raise RuntimeError( RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one
mrk-its commented 3 months ago

I hope it is fixed now, can you check current version?

Mariusthvdb commented 3 months ago

thanks I will, and report back please point me to the lines in the code you changed for this?

btw, you did not incorporate:

  "import_executor": true,

in the manifest yet, and while debugging this, Bdraco suggested all CC's to use that. I am not sure this is still required, or whether HA core has built in guards for that now, but please check with Nick (BDraco) whether you still should. nevermind that, it's imported by default. All good

considering this is in the startup log:

2024-04-22 11:03:22.483 DEBUG (MainThread) [homeassistant.loader] Component blitzortung import took 9.395 seconds (loaded_executor=True)
2024-04-22 11:03:22.484 INFO (MainThread) [homeassistant.setup] Setting up blitzortung
2024-04-22 11:03:22.484 INFO (MainThread) [homeassistant.setup] Setup of domain blitzortung took 0.00 seconds
2024-04-22 11:03:22.492 DEBUG (MainThread) [homeassistant.setup] Phase config_entry_setup for blitzortung (204410fa427cbf9ba1492617bc1d291e) took 0.01s (elapsed=0.01s) (wait_time=0.00s)

I guess all is ok ;-)

2024-04-22 11:03:31.853 DEBUG (MainThread) [homeassistant.loader] Importing platforms for blitzortung executor=['sensor'] loop=[] took 9.36s
2024-04-22 11:03:31.864 DEBUG (MainThread) [homeassistant.setup] Phase config_entry_platform_setup for blitzortung (204410fa427cbf9ba1492617bc1d291e) took 0.01s (elapsed=0.01s) (wait_time=0.00s)
2024-04-22 11:03:31.864 DEBUG (MainThread) [homeassistant.loader] Importing platforms for blitzortung executor=['geo_location'] loop=[] took 9.37s
2024-04-22 11:03:31.864 DEBUG (MainThread) [homeassistant.setup] Phase config_entry_platform_setup for blitzortung (204410fa427cbf9ba1492617bc1d291e) took 0.00s (elapsed=0.00s) (wait_time=0.00s)

9.36 seems a long time, though if not blocking, that probably does not harm, and it's just awaiting response from the resource?

Now lets await some lightning...

bdraco commented 3 months ago

The import executor is single threaded so 9.36s might just mean there was a line at the time. You would need to test with only a single integration enabled to get the actual import time

bdraco commented 3 months ago

For the non thread safe operations, make sure you don’t use the async API from a thread.

For example if you need to create a task in the event loop from a thread, call hass.create_task and not hass.async_create_task as while the async call is faster it is only safe to do when running in the main thread / event loop

andrewjswan commented 3 months ago

I hope it is fixed now, can you check current version?

2024-04-22 03:00:09.763 INFO (Thread-11 (_thread_main)) [custom_components.blitzortung.mqtt] Disconnected from MQTT server blitzortung.ha.sed.pl:1883 (7)
2024-04-22 03:00:09.983 ERROR (SyncWorker_19) [homeassistant.util.logging] Exception in _on_connection_change when dispatching 'blitzortung_mqtt_disconnected': ()
Traceback (most recent call last):
  File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change
    sensor.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1181, in _async_write_ha_state
    hass.states.async_set(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2181, in async_set
    self._bus._async_fire(  # pylint: disable=protected-access
  File "/usr/src/homeassistant/homeassistant/core.py", line 1459, in _async_fire
    self._hass.async_add_hass_job(job, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 690, in async_add_hass_job
    self.loop.call_soon(hassjob.target, *args)
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 795, in call_soon
    self._check_thread()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 832, in _check_thread
    raise RuntimeError(
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one

2024-04-22 03:00:09.983 ERROR (SyncWorker_21) [homeassistant.util.logging] Exception in _on_connection_change when dispatching 'blitzortung_mqtt_disconnected': ()
Traceback (most recent call last):
  File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change
    sensor.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1181, in _async_write_ha_state
    hass.states.async_set(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2181, in async_set
    self._bus._async_fire(  # pylint: disable=protected-access
  File "/usr/src/homeassistant/homeassistant/core.py", line 1459, in _async_fire
    self._hass.async_add_hass_job(job, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 690, in async_add_hass_job
    self.loop.call_soon(hassjob.target, *args)
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 795, in call_soon
    self._check_thread()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 832, in _check_thread
    raise RuntimeError(
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one

2024-04-22 03:00:09.985 ERROR (SyncWorker_56) [homeassistant.util.logging] Exception in _on_connection_change when dispatching 'blitzortung_mqtt_disconnected': ()
Traceback (most recent call last):
  File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change
    sensor.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1181, in _async_write_ha_state
    hass.states.async_set(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2181, in async_set
    self._bus._async_fire(  # pylint: disable=protected-access
  File "/usr/src/homeassistant/homeassistant/core.py", line 1459, in _async_fire
    self._hass.async_add_hass_job(job, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 690, in async_add_hass_job
    self.loop.call_soon(hassjob.target, *args)
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 795, in call_soon
    self._check_thread()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 832, in _check_thread
    raise RuntimeError(
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one

2024-04-22 03:00:09.986 ERROR (SyncWorker_55) [homeassistant.util.logging] Exception in _on_connection_change when dispatching 'blitzortung_mqtt_disconnected': ()
Traceback (most recent call last):
  File "/config/custom_components/blitzortung/__init__.py", line 222, in _on_connection_change
    sensor.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 998, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1181, in _async_write_ha_state
    hass.states.async_set(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2181, in async_set
    self._bus._async_fire(  # pylint: disable=protected-access
  File "/usr/src/homeassistant/homeassistant/core.py", line 1459, in _async_fire
    self._hass.async_add_hass_job(job, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 690, in async_add_hass_job
    self.loop.call_soon(hassjob.target, *args)
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 795, in call_soon
    self._check_thread()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 832, in _check_thread
    raise RuntimeError(
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one
bdraco commented 2 months ago
diff --git a/custom_components/blitzortung/__init__.py b/custom_components/blitzortung/__init__.py
index d56cc39..e069388 100644
--- a/custom_components/blitzortung/__init__.py
+++ b/custom_components/blitzortung/__init__.py
@@ -10,7 +10,7 @@ import voluptuous as vol
 from homeassistant.components.sensor import SensorDeviceClass
 from homeassistant.config_entries import ConfigEntry
 from homeassistant.const import CONF_LATITUDE, CONF_LONGITUDE, CONF_NAME, UnitOfLength
-from homeassistant.core import HomeAssistant
+from homeassistant.core import callback, HomeAssistant
 from homeassistant.helpers.dispatcher import async_dispatcher_connect
 from homeassistant.helpers.event import async_track_time_interval

@@ -215,6 +215,7 @@ class BlitzortungCoordinator:
             )
         )

+    @callback
     def _on_connection_change(self, *args, **kwargs):
         if self.unloading:
             return

That should fix the issue reported above

Mariusthvdb commented 2 months ago

did you get it to work with that @andrewjswan ? I edited the init but entities remain unavailable to me

andrewjswan commented 2 months ago

did you get it to work with that @andrewjswan ? I edited the init but entities remain unavailable to me

Fixed it, restarted the HA, there are sensors, but the value is unknown because no lightning.

Mariusthvdb commented 2 months ago

odd, thats what I did too..

where do we add the:

    @callback
    def _on_connection_change(self, *args, **kwargs):
        if self.unloading:
            return

? I might have put it erroneously before the 2 @property definitions in that case, now making that line 316 in my init.py

andrewjswan commented 2 months ago

odd, thats what I did too..

Don't forget to change?

from homeassistant.core import HomeAssistant

to

from homeassistant.core import callback, HomeAssistant
andrewjswan commented 2 months ago

where do we add the:

I add @callback in 218 line before def _on_connection_change(self, *args, **kwargs):

Mariusthvdb commented 2 months ago

Right that did it, I completely overlooked that spot in Nicks suggestion, and, that we only had to add the @callback.

I now am seeing this again:

Scherm­afbeelding 2024-05-01 om 16 21 31

so at least we have progress ;-) thanks to the both of you

Mariusthvdb commented 2 months ago

now if we get the probably easy fix for the deprecated typing alias, we could keep using this integration probably without all of the warnings:

https://developers.home-assistant.io/blog/2024/04/08/deprecated-backports-and-typing-aliases

in mqtt.py

mathieucarbou commented 2 months ago

Hello, I got the issue today after HA update, applied the diff above and restarted. It works now. Thanks!

mrk-its commented 2 months ago

New version 1.3.3 released with your fixes. Thanks!