search

elad-bar / ha-blueiris

Integration with Blue Iris Video Security Software
184 stars 43 forks source link

Error in Core Logs #236

Closed DeFlanko closed 1 month ago

DeFlanko commented 3 months ago 
2024-08-07 10:37:13.260 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "ON" }
2024-08-07 10:37:13.262 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 10:37:13.262 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Identified first time | Blue Iris NVR Front_Low_205 Audio
2024-08-07 10:37:13.262 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 10:37:13.442 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/config/custom_components/blueiris/models/base_entity.py", line 134, in _async_schedule_immediate_update
    self._immediate_update(previous_state)
  File "/config/custom_components/blueiris/binary_sensors/audio.py", line 66, in _immediate_update
    self.hass.loop.call_later(self.hass, 2, turn_off_automatically)
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 761, in call_later
    timer = self.call_at(self.time() + delay, callback, *args,
                         ~~~~~~~~~~~~^~~~~~~
TypeError: unsupported operand type(s) for +: 'float' and 'HomeAssistant'

It appears to be on the MQTT messages being sent from BI to Homeassistant? Is there anything to be done about these?

kramttocs commented 3 months ago

If you want to try this- Remove the 'self.hass' parameter on line 66 here. Save and restart HA. image

DeFlanko commented 3 months ago

the whole line 66 or just the self.hass bit?

kramttocs commented 3 months ago

just self.hass,

From some quick digging, doesn't seem like call_later accepts three arguments. So we just want it to have 2, turn_off_automatically

Keep me updated. I don't use audio triggers so haven't ever set the messages up.

DeFlanko commented 3 months ago

made the change. On reboot the Core logs look like:

2024-08-07 20:42:11.732 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam203/Status: { "type": "Motion_A", "trigger": "OFF" }
2024-08-07 20:42:11.735 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam201/Status: { "type": "Audio", "trigger": "OFF" }
2024-08-07 20:42:11.738 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam200/Status: { "type": "Motion_A", "trigger": "ON" }
2024-08-07 20:42:11.739 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_High_200 Motion updated from False to True
2024-08-07 20:42:11.739 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Blue Iris NVR Alerts updated from False to True
2024-08-07 20:42:11.740 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "ON" }
2024-08-07 20:42:11.742 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 20:42:11.742 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Identified first time | Blue Iris NVR Front_Low_205 Audio
2024-08-07 20:42:11.742 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 20:42:11.743 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam202/Status: { "type": "Audio", "trigger": "OFF" }
2024-08-07 20:42:11.744 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Irrelevant 0.002223968505859375 seconds ago | Blue Iris NVR Front_Low_205 Audio
2024-08-07 20:42:13.743 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback BlueIrisAudioBinarySensor._immediate_update.<locals>.turn_off_automatically() at /config/custom_components/blueiris/binary_sensors/audio.py:34 (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
TypeError: BlueIrisAudioBinarySensor._immediate_update.<locals>.turn_off_automatically() missing 1 required positional argument: 'now'

image

kramttocs commented 3 months ago

Guess that's progress. We could pass an arg as the third argument for 'now' but I don't see why we need it since it appears to only be used in a debug message.

On line 34 and 35 make it:

 async def turn_off_automatically():
            _LOGGER.debug(f"Audio alert off | {self.name}")

We are just removing the references to "now"

DeFlanko commented 3 months ago

i will blindly accept whatever changes lol

kramttocs commented 3 months ago

Can you try that new change (two line changes)and let me know?

DeFlanko commented 3 months ago

trying now.

DeFlanko commented 3 months ago 
2024-08-07 22:15:19.136 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "ON" }
2024-08-07 22:15:19.139 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 22:15:19.139 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Identified first time | Blue Iris NVR Front_Low_205 Audio
2024-08-07 22:15:19.139 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-07 22:15:21.140 WARNING (MainThread) [py.warnings] /usr/local/lib/python3.12/asyncio/events.py:88: RuntimeWarning: coroutine 'BlueIrisAudioBinarySensor._immediate_update.<locals>.turn_off_automatically' was never awaited
  self._context.run(self._callback, *self._args)

2024-08-07 22:15:24.142 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam200/Status: { "type": "Motion_A", "trigger": "ON" }
2024-08-07 22:15:24.143 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_High_200 Motion updated from False to True
2024-08-07 22:15:24.143 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Identified 5.0044310092926025 seconds ago | Blue Iris NVR Front_Low_205 Audio
2024-08-07 22:15:29.841 WARNING (MainThread) [systembridgeconnector.websocket_client.WebSocketClient] [Get data WebSocket Listener]: {'id': 'bb6b6ab08bab47d4b9304f2aef4afac9', 'type': 'ERROR', 'data': {}, 'subtype': None, 'message': 'Cannot find data for module', 'module': 'media'}
2024-08-07 22:15:33.152 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "OFF" }
2024-08-07 22:15:33.154 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from True to False
2024-08-07 22:15:33.154 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from True to False
2024-08-07 22:15:37.157 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam200/Status: { "type": "Motion_A", "trigger": "OFF" }
2024-08-07 22:15:37.158 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_High_200 Motion updated from True to False
2024-08-07 22:15:38.243 DEBUG (MainThread) [custom_components.blueiris.managers.home_assistant] Updating @2024-08-08 05:15:38.243370+00:00
2024-08-07 22:15:38.243 DEBUG (MainThread) [custom_components.blueiris.api.blue_iris_api] Updating data from BI Server (Blue Iris NVR)
2024-08-07 22:15:38.243 DEBUG (MainThread) [custom_components.blueiris.api.blue_iris_api] Retrieving camera list
2024-08-07 22:15:38.558 DEBUG (MainThread) [custom_components.blueiris.api.blue_iris_api] Status of http://172.10.1.12:1930/json: 200
kramttocs commented 3 months ago

That makes sense. The solution may be to add this at the top:import asyncio and then change the first line we touched to:

self.hass.loop.call_later(2, asyncio.create_task, turn_off_automatically)

DeFlanko commented 3 months ago 
import asyncio
from datetime import datetime
import logging

from homeassistant.components.binary_sensor import STATE_OFF

from ..helpers.const import *
from .base import BlueIrisBinarySensor

_LOGGER = logging.getLogger(__name__)

class BlueIrisAudioBinarySensor(BlueIrisBinarySensor):
    """Representation a binary sensor that is updated by MQTT."""

    def __init__(self):
        """Initialize the MQTT binary sensor."""
        super().__init__()

        self._last_alert = None

    async def async_added_to_hass_local(self):
        """Subscribe MQTT events."""
        _LOGGER.debug(f"Added new {self.name}")

    def _immediate_update(self, previous_state: bool):
        if previous_state != self.entity.state:
            _LOGGER.debug(
                f"{self.name} updated from {previous_state} to {self.entity.state}"
            )

        is_trigger_off = self.state == STATE_OFF
        current_timestamp = datetime.now().timestamp()

        async def turn_off_automatically():
            _LOGGER.debug(f"Audio alert off | {self.name}")

            self.entity_manager.set_mqtt_state(self.topic, self.event_type, False)

            self.hass.async_create_task(self.ha.async_update(None))

        if is_trigger_off:
            self._last_alert = None
            super()._immediate_update(previous_state)

        else:
            should_alert = True

            if self._last_alert is None:
                message = "Identified first time"
            else:
                time_since = current_timestamp - self._last_alert
                message = f"{time_since} seconds ago"

                if current_timestamp - self._last_alert > AUDIO_EVENT_LENGTH:
                    message = f"Identified {message}"
                else:
                    message = f"Irrelevant {message}"
                    should_alert = False

            if should_alert:
                _LOGGER.debug(f"Audio alert on, {message} | {self.name}")

                self._last_alert = current_timestamp
                super()._immediate_update(previous_state)

                self.hass.loop.call_later(2, asyncio.create_task, turn_off_automatically)
            else:
                _LOGGER.debug(f"Audio alert on, {message} | {self.name}")

Saving , restarting

DeFlanko commented 3 months ago 
2024-08-08 08:13:57.226 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam203/Status: { "type": "Motion_A", "trigger": "OFF" }
2024-08-08 08:13:57.229 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam201/Status: { "type": "Audio", "trigger": "OFF" }
2024-08-08 08:13:57.231 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam200/Status: { "type": "Motion_A", "trigger": "OFF" }
2024-08-08 08:13:57.233 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "ON" }
2024-08-08 08:13:57.234 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-08 08:13:57.234 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Identified first time | Blue Iris NVR Front_Low_205 Audio
2024-08-08 08:13:57.234 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from False to True
2024-08-08 08:13:57.234 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Blue Iris NVR Alerts updated from False to True
2024-08-08 08:13:57.236 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam202/Status: { "type": "Motion_A", "trigger": "OFF" }
2024-08-08 08:13:57.237 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Audio alert on, Irrelevant 0.002649068832397461 seconds ago | Blue Iris NVR Front_Low_205 Audio
2024-08-08 08:13:58.255 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.main] Received BlueIris Message - BlueIris/Cam205/Status: { "type": "Audio", "trigger": "OFF" }
2024-08-08 08:13:58.257 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.audio] Blue Iris NVR Front_Low_205 Audio updated from True to False
2024-08-08 08:13:58.257 DEBUG (MainThread) [custom_components.blueiris.binary_sensors.base] Blue Iris NVR Front_Low_205 Audio updated from True to False
2024-08-08 08:13:59.236 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback create_task(<function Blu...x7ff568beede0>) at /usr/local/lib/python3.12/asyncio/tasks.py:412 (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/asyncio/tasks.py", line 420, in create_task
    task = loop.create_task(coro)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 458, in create_task
    task = tasks.Task(coro, loop=self, name=name, context=context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: a coroutine was expected, got <function BlueIrisAudioBinarySensor._immediate_update.<locals>.turn_off_automatically at 0x7ff568beede0>

more logs -- will be in meeting most of today -- wont be able to respond as quickly.

kramttocs commented 3 months ago

I'll stop making you the guinea pig :) Will try to set this up and see what's going on.

DeFlanko commented 3 months ago

i dont mind helping -- i just wanted to set expectations for responses today =)

kramttocs commented 3 months ago

Ah, try this. Just adding () to turn_off_automatically

self.hass.loop.call_later(2, asyncio.create_task, turn_off_automatically())

DeFlanko commented 3 months ago

i don't see errors anymore in Core logs!

kramttocs commented 3 months ago

Good deal! Let me know if you see anything odd with the audio sensor behavior.

DeFlanko commented 3 months ago

will do!

DeFlanko commented 3 months ago

on a side note, are you the only one maintaining this integration right now?

kramttocs commented 3 months ago

Elad-bar still takes care of some things but he is no longer using BI. I am mainly just trying to keep it functional and updated with the HA breaking changes. I'd love to add some features but I'll be the first to admit that I don't understand some of what is going on here. I do believe things have progressed enough on the HA side that a lot of functions could now be cleaned up to a more standard approach (especially the config flow stuff) but I'd first have to understand what they are doing :D

DeFlanko commented 3 months ago

If i have time id like to contribute where i can.