search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.44k stars 30.68k forks source link

Reolink Baichuan decode errors #129905

Open RobertD502 opened 1 day ago

RobertD502 commented 1 day ago

The problem

Decode errors are filling up my log book for all 4 Reolink cameras - reporting the issue to help get it fixed during the beta. See attached log and debug info.

Edit: Seems like this may be the potential cause of my Home Assistant locking up and restarts being delayed.

What version of Home Assistant Core has the issue?

2024.11.0b6

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Reolink

Link to integration documentation on our website

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

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: reolink_aio.baichuan.tcp_protocol
Source: /usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py:67
First occurred: 11:55:30 AM (183 occurrences)
Last logged: 12:12:14 PM

Baichuan host 192.168.1.154: error during parsing of received data: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte
Baichuan host 192.168.1.70: error during parsing of received data: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte
Baichuan host 192.168.1.199: error during parsing of received data: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte
Baichuan host 192.168.1.78: error during parsing of received data: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py", line 123, in parse_data
    self._push_callback(rec_cmd_id, data_chunk, len_header)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 230, in _push_callback
    rec_body = self._decrypt(data, len_header)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 206, in _decrypt
    rec_body = self._aes_decrypt(enc_body)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 192, in _aes_decrypt
    return cipher.decrypt(data).decode("utf8")
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py", line 65, in data_received
    self.parse_data()
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py", line 139, in parse_data
    self.parse_data()
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py", line 139, in parse_data
    self.parse_data()
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/tcp_protocol.py", line 123, in parse_data
    self._push_callback(rec_cmd_id, data_chunk, len_header)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 230, in _push_callback
    rec_body = self._decrypt(data, len_header)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 206, in _decrypt
    rec_body = self._aes_decrypt(enc_body)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/baichuan/baichuan.py", line 192, in _aes_decrypt
    return cipher.decrypt(data).decode("utf8")
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xed in position 0: invalid continuation byte

Additional information

home-assistant_reolink_2024-11-05T17-18-21.020Z.log

home-assistant[bot] commented 1 day ago

Hey there @starkillerog, mind taking a look at this issue as it has been labeled with an integration (reolink) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `reolink` 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 reolink` 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)

reolink documentation reolink source (message by IssueLinks)

starkillerOG commented 1 day ago

@RobertD502 I have made improvements to the logging in this PR: https://github.com/home-assistant/core/pull/129914 That will ensure only 1 exception is logged per camera per command_id. (so in your case probably 4 errors). And it will give me additional details in the log to see if I can solve the actual cause of the issue.

Currently the log does not provide enough information for me to solve this.

RobertD502 commented 1 day ago

Edited the manifest file to pull the new package - will get the log to you once home assistant restarts. It looks like the following log is related to why I've been having issues with restarts taking a few minutes instead of seconds:


2024-11-05 17:04:54.171 WARNING (MainThread) [homeassistant.core] Timed out waiting for integrations to stop, the shutdown will continue
2024-11-05 17:04:54.171 WARNING (MainThread) [homeassistant.core] Shutdown stage 'stop integrations': still running: <Task pending name='Task-16673' coro=<async_setup.<locals>.shutdown() running at /usr/src/homeassistant/homeassistant/components/stream/__init__.py:265> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>
2024-11-05 17:04:54.175 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_proto.py", line 262, in data_received
    messages, upgraded, tail = self._parser.feed_data(data)
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "aiohttp/_http_parser.pyx", line 563, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadHttpMessage: 400, message:
  Expected HTTP/:

    b'$'
      ^

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_reqrep.py", line 1058, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/streams.py", line 643, in read
    await self._waiter
aiohttp.http_exceptions.HttpProcessingError: 400, message:
  Expected HTTP/:

    b'$'
      ^

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/reolink/host.py", line 513, in stop
    await self.disconnect()
  File "/usr/src/homeassistant/homeassistant/components/reolink/host.py", line 433, in disconnect
    await self._api.unsubscribe()
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5798, in unsubscribe
    await self.unsubscribe(SubType.push)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5813, in unsubscribe
    await self.subscription_send(headers, xml)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5577, in subscription_send
    response = await self._aiohttp_session.post(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 690, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_reqrep.py", line 1060, in start
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message="Expected HTTP/:\n\n  b'$'\n    ^", url='http://192.168.1.78:8000/onvif/event_service'
2024-11-05 17:04:54.176 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_proto.py", line 262, in data_received
    messages, upgraded, tail = self._parser.feed_data(data)
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "aiohttp/_http_parser.pyx", line 563, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadHttpMessage: 400, message:
  Expected HTTP/:

    b'$\x02\x01\t\x80\xe1\xe8w(\xac\x89\x0b@\x9eQ\xc9'
      ^

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_reqrep.py", line 1058, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/streams.py", line 643, in read
    await self._waiter
aiohttp.http_exceptions.HttpProcessingError: 400, message:
  Expected HTTP/:

    b'$\x02\x01\t\x80\xe1\xe8w(\xac\x89\x0b@\x9eQ\xc9'
      ^

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/reolink/host.py", line 513, in stop
    await self.disconnect()
  File "/usr/src/homeassistant/homeassistant/components/reolink/host.py", line 433, in disconnect
    await self._api.unsubscribe()
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5798, in unsubscribe
    await self.unsubscribe(SubType.push)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5813, in unsubscribe
    await self.subscription_send(headers, xml)
  File "/usr/local/lib/python3.12/site-packages/reolink_aio/api.py", line 5577, in subscription_send
    response = await self._aiohttp_session.post(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 690, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client_reqrep.py", line 1060, in start
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message="Expected HTTP/:\n\n  b'$\\x02\\x01\\t\\x80\\xe1\\xe8w(\\xac\\x89\\x0b@\\x9eQ\\xc9'\n    ^", url='http://192.168.1.70:8000/onvif/event_service'

Edit: Prior to the shutdown timing out, this is seen:

2024-11-06 07:55:06.545 ERROR (MainThread) [reolink_aio.baichuan.baichuan] Baichuan host 192.168.1.199: failed to logout: Baichuan host 192.168.1.199: received status code 400
2024-11-06 07:55:06.545 ERROR (MainThread) [reolink_aio.baichuan.baichuan] Baichuan host 192.168.1.154: failed to logout: Baichuan host 192.168.1.154: received status code 400
2024-11-06 07:55:06.545 ERROR (MainThread) [reolink_aio.baichuan.baichuan] Baichuan host 192.168.1.78: failed to logout: Baichuan host 192.168.1.78: received status code 400
2024-11-06 07:55:06.545 ERROR (MainThread) [reolink_aio.baichuan.baichuan] Baichuan host 192.168.1.70: failed to logout: Baichuan host 192.168.1.70: received status code 400
2024-11-06 07:56:46.522 WARNING (MainThread) [homeassistant.core] Timed out waiting for integrations to stop, the shutdown will continue
2024-11-06 07:56:46.522 WARNING (MainThread) [homeassistant.core] Shutdown stage 'stop integrations': still running: <Task pending name='Task-198291' coro=<async_setup.<locals>.shutdown() running at /usr/src/homeassistant/homeassistant/components/stream/__init__.py:265> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>
2024-11-06 07:57:46.523 WARNING (MainThread) [homeassistant.core] Timed out waiting for final writes to complete, the shutdown will continue
2024-11-06 07:57:46.523 WARNING (MainThread) [homeassistant.core] Shutdown stage 'final write': still running: <Task pending name='Task-198291' coro=<async_setup.<locals>.shutdown() running at /usr/src/homeassistant/homeassistant/components/stream/__init__.py:265> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[set.remove()]>
RobertD502 commented 1 day ago

Log with latest backend library: home-assistant_reolink_2024-11-05T22-13-41.709Z.log