@allenporter I also found this, which may be useful:
2023-01-03 07:46:42.233 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 195.249.79.150 for /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA1OTQ4IiwgIm46MSJd/thumbnail using signed request
2023-01-03 07:46:42.234 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA1OTQ4IiwgIm46MSJd/thumbnail to 195.249.79.150 (auth: True)
2023-01-03 07:46:42.246 DEBUG (SyncWorker_15) [homeassistant.components.nest.media_source] Reading event media from disk store: /config/nest/event_media/34bf6f2934862c9538f6f3ace8125419/1671638900-doorbell_chime_thumb.gif
2023-01-03 07:46:42.307 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 195.249.79.150 for /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA1OTQ4IiwgIm46MSJd/thumbnail using signed request
2023-01-03 07:46:42.307 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA1OTQ4IiwgIm46MSJd/thumbnail to 195.249.79.150 (auth: True)
2023-01-03 07:46:42.310 DEBUG (SyncWorker_4) [homeassistant.components.nest.media_source] Reading event media from disk store: /config/nest/event_media/34bf6f2934862c9538f6f3ace8125419/1671638900-doorbell_chime_thumb.gif
2023-01-03 07:46:42.714 DEBUG (Thread-14 (_run)) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 503 The StreamingPull stream closed for an expected reason and should be recreated, which is done automatically if using Cloud Pub/Sub client libraries. Refer to https://cloud.google.com/pubsub/docs/pull#streamingpull for more information.
2023-01-03 07:46:42.714 DEBUG (Thread-14 (_run)) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 503 The StreamingPull stream closed for an expected reason and should be recreated, which is done automatically if using Cloud Pub/Sub client libraries. Refer to https://cloud.google.com/pubsub/docs/pull#streamingpull for more information.
2023-01-03 07:46:42.717 INFO (Thread-14 (_run)) [google.api_core.bidi] Re-established stream
Did you see the issue during this time? The lines “Serving /api/nest/event_media/…” are showing the requests arriving, then reading the media files from disk so you can see exactly which files it was looking for.
Now that you mention, I don’t recognize that event. There’s nothing in my Google Nest event log and my automation hasn’t been fired at 07:46. The closest event was at 07:31, but the event ID from the “Serving /api/nest/event_media/…” log statement does not match the one I received at 07.31 from my HA automation.
That is the time when an automation ran or when the notification happened (what we are debugging right?) or when it was shown in the media player. That is not a new event.
The automation ran at 7:30. I received a notification but with no image as usual.
The “Serving /api/nest/event_media/…” log statement was written at 7:46. I don’t know what event it is refering to, because there is no event at that time.
I only have an MP4 from 7:31, but it was never attached and I cannot find any homeassistant.components.http.view log statements from 7:30-7:31.
The images are just to show you that I received the event with no image attachment, and that I cannot find any events from 7:46
I mean, I need you to tell me… were you viewing the media player to check if the media existed?
From this test we can see the media was recorded successfully. I don’t think I see from this detail if there is a problem with the automation requesting the image, but it doesn’t appear to arrive.
I was just wondering why the request was made at 7:46, when no event happened during that time.
But yes I agree. The media is indeed recorded and saved successfully, but still no image in the notification. I can see from another thread, that I’m not the only one having this problem:
Yes, it seems like the mobile app isn’t making the request to fetch the image? Not sure if thats the same request and it happens much later or what, but it might be good to try again and see what a normal working path looks like then what the failure one looks like. I recommend excluding stuff outside of the time range that is relevant to the notifications.
What do you mean exactly by " the mobile app isn’t making the request to fetch the image?". Are you referring to the “/api/nest/event_media/…” request? Because I’m pretty sure it does, but the image doesn’t seem to be available at the time it is requesting the image.
I’ve recently tried to set a delay of 1 minute.
So just to summarize:
Person detected event triggers
1 minute delay
Send notification and attach image and video
It seems to work 90% of the time now, which is better than 1%, but there’s as you can see still a few clip previews missing.
Hi,
We turned up logging so we can see the requests arriving to home assistant. My impression is we saw the media saved on disk but didn’t see the requests for the media in the logs.
The media is being requested by the automation before it is done saving it
The media is never saved
Because as mentioned. It helped a lot after setting a delay for 1 minute, so that must mean that it just needs a little time to get ready, but in situations where this is not the case, I get the following error message in the log:
2023-01-08 12:56:02.101 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2023-01-08 12:56:02.102 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.392832 seconds.
2023-01-08 12:56:04.591 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
2023-01-08 12:56:05.653 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 87.49.147.137 for /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA2MTk3IiwgIjY4OTAzNjY3OCJd using bearer token
2023-01-08 12:56:05.653 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/nest/event_media/34bf6f2934862c9538f6f3ace8125419/WyIxNjMzMjA2MTk3IiwgIjY4OTAzNjY3OCJd to 87.49.147.137 (auth: True)
2023-01-08 12:56:05.662 DEBUG (MainThread) [google_nest_sdm.event_media] No persisted media for event id <EventToken event_session_id1633206197 event_id=689036678>
2023-01-08 12:56:05.662 DEBUG (MainThread) [homeassistant.components.nest] No event found for event_id 'WyIxNjMzMjA2MTk3IiwgIjY4OTAzNjY3OCJd'
This is from one of the two notifications with a 404 you see on the attached images where it says “2 t. siden” and “3 t. siden”. Here I waited 1 minute, and you can see the request is being made by the HTTP service, but no persisted media for the given event is found.
Do you have the log entries for that event where it is received and published?
I suggest disabling everything under google.cloud.pubsub_v1.subscriber as it is not really relevant.
OK thanks for the detail. I’m finding it difficult to read this one small piece at a time, os how about we move this into a github issue under home assistant Core? That will help me since it will ask you for full diagnostics information which will include details about all your devices, etc. Then you can include the logs for one single end-to-end event from the time the message is delivered to the time the notification is fired, including your automation examples, etc in one place (excluding the stuff that isn’t relevant). Would you be up for doing that? I think we have everything we need for a full issue now.
Can someone link to that github issue? I think pretty much everyone experiences this with nest doorbell. Ive got a bad feeling it basically takes google minutes to upload the MP4, making it unusable for the use cases we care about.
