Looks like postcards are not updated in Home Assistant
RuudvanMunster opened this issue · 16 comments
It looks like postcards are not updated in Home Assistant. I get the following logbook messages:
1.
Deze fout is ontstaan door een aangepaste integratie.
Logger: custom_components.birdbuddy
Source: helpers/update_coordinator.py:322
Integration: Bird Buddy (documentation, issues)
First occurred: 11 november 2023 om 17:48:09 (2 occurrences)
Last logged: 09:01:12
Error fetching birdbuddy data: 0, message='Attempt to decode JSON with unexpected mimetype: text/html', url=URL('https://graphql.app-api.prod.aws.mybirdbuddy.com/graphql')
Error fetching birdbuddy data: INTERNAL_SERVER_ERROR: {'message': 'Cannot execute GraphQL operations after the server has stopped.', 'extensions': {'code': 'INTERNAL_SERVER_ERROR'}}
Logger: homeassistant.components.automation.birdbuddy_process_postcard
Source: components/automation/__init__.py:655
Integration: Automatisering (documentation, issues)
First occurred: 10 november 2023 om 23:24:25 (1 occurrences)
Last logged: 10 november 2023 om 23:24:25
While executing automation automation.birdbuddy_process_postcard
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 655, in async_trigger
await self.action_script.async_run(
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1578, in async_run
return await asyncio.shield(run.async_run())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 420, in async_run
await self._async_step(log_exceptions=False)
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 470, in _async_step
self._handle_exception(
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 493, in _handle_exception
raise exception
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2035, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2072, in _execute_service
return await target(service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/birdbuddy/__init__.py", line 106, in handle_collect_postcard
await coordinator.handle_collect_postcard(service.data)
File "/config/custom_components/birdbuddy/coordinator.py", line 144, in handle_collect_postcard
success = await self.client.finish_postcard(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/client.py", line 456, in finish_postcard
for sighting, mod in report.sighting_finishing_strategies(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 207, in sighting_finishing_strategies
matches = self.highest_confidence_matches
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 249, in highest_confidence_matches
matches = {
^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 251, in <dictcomp>
i["matchToken"]: max(
^^^^
ValueError: max() arg is an empty sequence
Logger: homeassistant.components.automation.birdbuddy_process_postcard
Source: helpers/script.py:468
Integration: Automatisering (documentation, issues)
First occurred: 10 november 2023 om 23:24:25 (1 occurrences)
Last logged: 10 november 2023 om 23:24:25
BirdBuddy process postcard: Error executing script. Unexpected error for call_service at pos 1: max() arg is an empty sequence
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
await getattr(self, handler)()
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 704, in _async_call_service_step
response_data = await self._async_run_long_action(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 666, in _async_run_long_action
return long_task.result()
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2035, in async_call
response_data = await coro
^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/core.py", line 2072, in _execute_service
return await target(service_call)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/birdbuddy/__init__.py", line 106, in handle_collect_postcard
await coordinator.handle_collect_postcard(service.data)
File "/config/custom_components/birdbuddy/coordinator.py", line 144, in handle_collect_postcard
success = await self.client.finish_postcard(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/client.py", line 456, in finish_postcard
for sighting, mod in report.sighting_finishing_strategies(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 207, in sighting_finishing_strategies
matches = self.highest_confidence_matches
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 249, in highest_confidence_matches
matches = {
^
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 251, in <dictcomp>
i["matchToken"]: max(
^^^^
ValueError: max() arg is an empty sequence
Stack traces (2) and (3) appear to be the same issue, and should be resolved in pybirdbuddy. This means we aren't able to determine a highest-confidence match, because there are no sighting AI matches of type "BIRD".
Stack trace (1) is a server error on BirdBuddy's end, and nothing we can do to "resolve" that here. However, we might be able to work around it or mitigate it, by attempting to retry the request, possibly after a backoff delay.
- does this happen consistently? Specifically the (2) and (3) errors - since (1) is obviously intermittent on BB's end
- how long has it been happening - i.e., did it start on a certain date?
- If you reload the integration, does anything change, or this keeps happening?
If it keeps happening, it might be worthwhile to enable debug logging while you reload, and wait for the issue to occur, and then see about sharing the debug logs. Since it's possible this could be a single postcard feed entry that has an unusual set of data in it.
However, I think even DEBUG logging won't contain the full BB GraphQL response 🤔
If not, we might need to increase the log level manually, which you can do by editing the file at /usr/local/lib/python3.11/site-packages/birdbuddy/__init__.py and uncomment the last line:
-# VERBOSE = 2 * VERBOSE
+VERBOSE = 2 * VERBOSEand then restart Home Assistant. This causes the super VERBOSE logs, including HTTP response data, to be logged at the DEBUG level, which Home Assistant will then show in logs when you enable debug logging for the integration. In the future I might replace the verbose logging with DEBUG, so that we can get logs like this straight from HA without having to edit this file.
For now I have a change up in pybirdbuddy to address the (2) and (3) issues. But I'm still curious to know why there's no species suggestions here. Also curious what the BB app shows for the oldest postcard in the feed (the one that HA is not able to process)
As I have restarted HA several times the last week, due to error in the Fibaro integration, my history does not go back further than November 10. It looks like there is some discontinuity during November 10 and 11. The photo’s of a certain bird (robin, roodborst in Dutch) from before November seem to have gone. However the photo in the Recent Visitor picture is from November 10!
It is difficult to say that it is happening consistently. Except for the last visitor picture. That is frozen at the November 10 robin. At least the time stamp is frozen. I can not find the picture of de Recent Visitor in the media library.
What also happened: in the library of the robin, my most frequent visitor of the last days, there were only video’s, no stills. There was a message that there were xxx incompatible images. After some action, I do not remember them exactly, the message disappeared and the stills appeared.
I already had enabled the logging earlier. It is enclosed with this message. Ik will start with the manual change of the logging.
The only directory with birdbuddy I could find is ./homeassistant/custom_components/birdbuddy.
It contains a file init.py. but I do not find the VERBOSE commands.
The only directory with birdbuddy I could find is ./homeassistant/custom_components/birdbuddy. It contains a file init.py. but I do not find the VERBOSE commands.
That's the directory for the HACS component. The path I mentioned above is where HA installed the pybirdbuddy dependency library into, and that's where the VERBOSE line is. The path is a full path (i.e., not starting from the ./homeassistant path where HA is installed). That's the exact path where the file should exist in your HA installation, based on the log entries that you provided in the initial report, e.g.:
File "/usr/local/lib/python3.11/site-packages/birdbuddy/sightings.py", line 251, in <dictcomp>
i["matchToken"]: max(
That site-packages/birdbuddy path is where HA installed pybirdbuddy to.
If you're using the File Editor add-on, it won't have access to the site-packages files of the HA container. Instead you would have to ssh to the server, and then attach to the docker container that is running HA. I'm not sure if there's any other way to allow HA to surface these VERBOSE logs otherwise 🤔 The lowest level HA can be set to enable is debug (see Logger log levels)
But we might be able to patch the pybirdbuddy value via the ha-birdbuddy init file you found at homeassistant/custom_components/birdbuddy/__init__.py, by adding something like this
import birdbuddy
birdbuddy.VERBOSE = 2 * birdbuddy.VERBOSE
I'm not sure if I'm totally following the rest of your explanation of sequence of events. I did notice that the BB feed appears to have started adding expiration dates to postcards - looks like they expire after 30 days.
I used the terminal to find the file. See the attached screendump about the failure to find it.
Is this the correct position for the logging statements?
This is what happens now. However this migth come from the templates I use to add some text to the picture of the last visitor. Maybe it is not relevant to solve the kernel problem now.
Logger: homeassistant.helpers.event
Source: helpers/template.py:570
First occurred: 22:46:10 (3 occurrences)
Last logged: 22:54:25
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.date() }} {{","}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().hour }}{{":"}}{{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().minute }}) renders=2>
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.date() }} {{","}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().hour }}{{":"}}{{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().minute }}) renders=6>
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.date() }} {{","}} {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().hour }}{{":"}}{{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().minute }}) renders=10>
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 568, in async_render
render_result = _render_with_context(self.template, compiled, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2231, in _render_with_context
return template.render(**kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/jinja2/environment.py", line 1301, in render
self.environment.handle_exception()
File "/usr/local/lib/python3.11/site-packages/jinja2/environment.py", line 936, in handle_exception
raise rewrite_traceback_stack(source=source)
File "<template>", line 1, in top-level template code
jinja2.exceptions.UndefinedError: 'homeassistant.util.read_only_dict.ReadOnlyDict object' has no attribute 'entity_picture'
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 694, in async_render_to_info
render_info._result = self.async_render(
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 570, in async_render
raise TemplateError(err) from err
homeassistant.exceptions.TemplateError: UndefinedError: 'homeassistant.util.read_only_dict.ReadOnlyDict object' has no attribute 'entity_picture'
Yes this does not look related to the BB integration.
After the VERBOSE logging change, then enabling debug logging on the integration should start logging actual HTTP response data.
Looks like I have recorded a good logging of the BirdBuddy integration. I also think I have found a possible reason for missing postcards. Although I do not understand all of it.
I had again a close look at your documentation and checked whether the blueprints were present. Do not ask me why, but they were not present. So I imported them from your site. Strange thing is, that the postcard were processed until a few days ago. So it worked either with out the blueprints available. Either the blueprints have disappeared a few days ago, when the system stopped with importing postcards. There is a gap in HA of a few days which is not in the app from BB.
In short some strange things but is seems top be working now.
For completeness I included the log stored when stopping the debug logging.
birdbuddy.log
However there is one thing that makes me wonder: altough there were 4 birds today, their presence is not visible in the statusline. This is different with earlier, before I restored the bleuprints.
If you had set up the automation using the Blueprint from the readme, and then that Blueprint disappeared, then that would cause your automation to no longer get triggered on a new postcard event, and also would not process those postcards.
After adding the Blueprint back, when you reload the integration, it should try to process those outstanding postcards automatically.
Altogether it is difficult to understand. It looks as if the pictures are complete in HA from Monday morning November 13, 8:00. It looks like since the beginning of November most birds have been missed, except for 1 bird last Friday. It is difficult to compare my app and HA because my app works in local time. And HA works in local time for the logging, but in UTC for the state parameters… I am trying to compensate for that using templates in the dashboard cards…
I do not have an explanation for the fact that the blueprints were missing. To me it looks like it did work most of the time without them. Could they have been present but invisible?
Currently, the problem with the time stamp of the last visitor is back again.
I’ll try to describe it:
The last visitor was, according to the app, 5 hours ago. That must be about 15:40
The picture of the last visitor in HA corresponds with that visit. However, the timestamp is: 2023-11-4, 9:16 (UTC), so 10:16 local time (Amsterdam). The Last Visitor logbook indeed says: 10:16:51.
According to the logbook, the processing of the last postcard was at: 2023-11-14 15:27:58.206, which is in the range of about 15:40. You can find this event in the log I posted earlier.
I use the following code for the last vistor card in my dashboard:
type: markdown
content: >
 {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}}
{{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.date()
}} {{","}} {{
states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().hour
}}{{":"}}{{
states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed.time().minute
}}
title: Recent Visitor
After a restart, because of an update, the picture of the last vistor is gone:
In the mean time I have changed this dashboard card into:
type: markdown
content: >-
 {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}}
{{
as_timestamp(states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed)
| timestamp_custom('%A %Y-%m-%d %H:%M') }}
title: Recent Visitor
This is the related logbook:
Logger: homeassistant.helpers.event
Source: helpers/template.py:570
First occurred: 22:19:37 (4 occurrences)
Last logged: 22:24:04
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ as_timestamp(states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed) | timestamp_custom('%A %Y-%m-%d %H:%M') }}) renders=2>
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ as_timestamp(states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed) | timestamp_custom('%A %Y-%m-%d %H:%M') }}) renders=6>
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ as_timestamp(states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed) | timestamp_custom('%A %Y-%m-%d %H:%M') }}) renders=10>
Error while processing template: Template<template=( {{ states.sensor.bird_buddy_ruudvanmunster_recent_visitor.state}} {{ as_timestamp(states.sensor.bird_buddy_ruudvanmunster_recent_visitor.last_changed) | timestamp_custom('%A %Y-%m-%d %H:%M') }}) renders=14>
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 568, in async_render
render_result = _render_with_context(self.template, compiled, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 2231, in _render_with_context
return template.render(**kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/jinja2/environment.py", line 1301, in render
self.environment.handle_exception()
File "/usr/local/lib/python3.11/site-packages/jinja2/environment.py", line 936, in handle_exception
raise rewrite_traceback_stack(source=source)
File "<template>", line 1, in top-level template code
jinja2.exceptions.UndefinedError: 'homeassistant.util.read_only_dict.ReadOnlyDict object' has no attribute 'entity_picture'
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 694, in async_render_to_info
render_info._result = self.async_render(
^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 570, in async_render
raise TemplateError(err) from err
homeassistant.exceptions.TemplateError: UndefinedError: 'homeassistant.util.read_only_dict.ReadOnlyDict object' has no attribute 'entity_picture'
I think I have found the reason for the main problem that regularly occurs here. When Home Assistant is restarted, the value of the entity “recent visitor” is reset to “unknown”.
That explains why the image disappears, as does the timestamp. And produces the corresponding entries in the logbook.
It is therefore not the case that the corresponding image is no longer present on the server. But the entity pointing to that picture has been erased.