Core: Nest (SDM) stops pulling messages from subscription after 10 minutes

Created on 26 Oct 2020  路  34Comments  路  Source: home-assistant/core

The problem

After a restart of HA the Nest (SDM) integrations stops pulling messages from the subscription

Environment

Problem-relevant configuration.yaml

nest:
  project_id: ****
  subscriber_id: projects/****/subscriptions/****
  client_id: ****.apps.googleusercontent.com
  client_secret: ****

Traceback/Error logs

No errors or logs present

Additional information

nest
Source
picture william-shuman

All 34 comments

Same for me. Also on b4 of HA. Also had the issue on b3

townsmcp picture townsmcp on 26 Oct 2020

nest documentation
nest source
(message by IssueLinks)

probot-home-assistant[bot] picture probot-home-assistant[bot] on 26 Oct 2020

Hey there @awarecan, @allenporter, mind taking a look at this issue as its been labeled with an integration (nest) you are listed as a codeowner for? Thanks!
(message by CodeOwnersMention)

probot-home-assistant[bot] picture probot-home-assistant[bot] on 26 Oct 2020

+1 0.118.0.dev0

Frobitz66 picture Frobitz66 on 27 Oct 2020

Thanks, i'll take a look.

allenporter picture allenporter on 27 Oct 2020

I am not yet able to reproduce the problem, both keeping hass open for 10 minutes and restarting it i keep getting messages ok, etc.

Up for turning up some logging? Maybe something like this in configuration.yaml could be useful:

logger:
  default: info
  logs:
    homeassistant.components.nest: debug
    homeassistant.components.nest.sensor_sdm: debug
    google.cloud.pubsub_v1: debug
    google.cloud.pubsub_v1.subscriber._protocol.leaser: debug
allenporter picture allenporter on 27 Oct 2020

@allenporter I have turned on logging for those 4 entries in configuraiton.yaml and rebooted. Running 0.117.0b5. My results are:

homeassistant.components.nest

No results

homeassistant.components.nest.sensor_sdm

No results

google.cloud.pubsub_v1

2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.dispatcher] Started helper thread Thread-CallbackRequestDispatcher
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.791155 seconds.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
2020-10-27 08:17:04 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Started helper thread Thread-Heartbeater
2020-10-27 08:17:10 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
2020-10-27 08:17:34 INFO (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Thread-Heartbeater exiting.

google.cloud.pubsub_v1.subscriber._protocol.leaser

2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.791155 seconds.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
2020-10-27 08:17:10 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.

For pub/sub setting I changed to the following when setting everything up (it was originally 1 day):
image

townsmcp picture townsmcp on 27 Oct 2020

I'm seeing a similar issue. Debug logs below.

homeassistant.components.nest
No results

homeassistant.components.nest.sensor_sdm
No results

google.cloud.pubsub_v1

    Line 444: 2020-10-27 11:56:51 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.dispatcher] Started helper thread Thread-CallbackRequestDispatcher
    Line 445: 2020-10-27 11:56:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 446: 2020-10-27 11:56:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.909091 seconds.
    Line 447: 2020-10-27 11:56:51 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
    Line 448: 2020-10-27 11:56:51 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
    Line 449: 2020-10-27 11:56:51 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Started helper thread Thread-Heartbeater
    Line 480: 2020-10-27 11:56:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 481: 2020-10-27 11:56:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.776127 seconds.
    Line 772: 2020-10-27 11:56:59 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 773: 2020-10-27 11:56:59 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.487191 seconds.
    Line 832: 2020-10-27 11:57:05 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 833: 2020-10-27 11:57:05 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 7.601643 seconds.
    Line 837: 2020-10-27 11:57:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 838: 2020-10-27 11:57:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.884608 seconds.
    Line 1006: 2020-10-27 11:57:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1007: 2020-10-27 11:57:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.659821 seconds.
    Line 1009: 2020-10-27 11:57:21 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
    Line 1011: 2020-10-27 11:57:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1012: 2020-10-27 11:57:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.971979 seconds.
    Line 1013: 2020-10-27 11:57:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1014: 2020-10-27 11:57:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 7.093749 seconds.
    Line 1015: 2020-10-27 11:57:33 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1016: 2020-10-27 11:57:33 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.719619 seconds.
    Line 1025: 2020-10-27 11:57:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1026: 2020-10-27 11:57:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.154542 seconds.
    Line 1027: 2020-10-27 11:57:41 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1028: 2020-10-27 11:57:41 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.478898 seconds.
    Line 1029: 2020-10-27 11:57:49 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1030: 2020-10-27 11:57:49 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.813093 seconds.
    Line 1031: 2020-10-27 11:57:50 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1032: 2020-10-27 11:57:50 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.598097 seconds.
    Line 1034: 2020-10-27 11:57:51 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
    Line 1035: 2020-10-27 11:57:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1036: 2020-10-27 11:57:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.057278 seconds.
    Line 1054: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1055: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.341283 seconds.
    Line 1056: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1057: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.172420 seconds.
    Line 1058: 2020-10-27 11:58:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1059: 2020-10-27 11:58:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.610312 seconds.
    Line 1060: 2020-10-27 11:58:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1061: 2020-10-27 11:58:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.048274 seconds.
    Line 1062: 2020-10-27 11:58:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1063: 2020-10-27 11:58:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 6.693533 seconds.
    Line 1072: 2020-10-27 11:58:19 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1073: 2020-10-27 11:58:19 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.739548 seconds.
    Line 1074: 2020-10-27 11:58:21 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1075: 2020-10-27 11:58:21 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.021955 seconds.
    Line 1076: 2020-10-27 11:58:21 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
    Line 1077: 2020-10-27 11:58:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1078: 2020-10-27 11:58:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.322306 seconds.
    Line 1085: 2020-10-27 11:58:34 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
    Line 1086: 2020-10-27 11:58:51 INFO (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Thread-Heartbeater exiting.`

google.cloud.pubsub_v1.subscriber._protocol.leaser
`   Line 445: 2020-10-27 11:56:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 446: 2020-10-27 11:56:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.909091 seconds.
    Line 447: 2020-10-27 11:56:51 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
    Line 480: 2020-10-27 11:56:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 481: 2020-10-27 11:56:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.776127 seconds.
    Line 772: 2020-10-27 11:56:59 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 773: 2020-10-27 11:56:59 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.487191 seconds.
    Line 832: 2020-10-27 11:57:05 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 833: 2020-10-27 11:57:05 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 7.601643 seconds.
    Line 837: 2020-10-27 11:57:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 838: 2020-10-27 11:57:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.884608 seconds.
    Line 1006: 2020-10-27 11:57:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1007: 2020-10-27 11:57:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.659821 seconds.
    Line 1011: 2020-10-27 11:57:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1012: 2020-10-27 11:57:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.971979 seconds.
    Line 1013: 2020-10-27 11:57:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1014: 2020-10-27 11:57:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 7.093749 seconds.
    Line 1015: 2020-10-27 11:57:33 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1016: 2020-10-27 11:57:33 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.719619 seconds.
    Line 1025: 2020-10-27 11:57:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1026: 2020-10-27 11:57:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.154542 seconds.
    Line 1027: 2020-10-27 11:57:41 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1028: 2020-10-27 11:57:41 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.478898 seconds.
    Line 1029: 2020-10-27 11:57:49 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1030: 2020-10-27 11:57:49 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.813093 seconds.
    Line 1031: 2020-10-27 11:57:50 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1032: 2020-10-27 11:57:50 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.598097 seconds.
    Line 1035: 2020-10-27 11:57:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1036: 2020-10-27 11:57:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.057278 seconds.
    Line 1054: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1055: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.341283 seconds.
    Line 1056: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1057: 2020-10-27 11:58:01 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.172420 seconds.
    Line 1058: 2020-10-27 11:58:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1059: 2020-10-27 11:58:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.610312 seconds.
    Line 1060: 2020-10-27 11:58:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1061: 2020-10-27 11:58:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 3.048274 seconds.
    Line 1062: 2020-10-27 11:58:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1063: 2020-10-27 11:58:12 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 6.693533 seconds.
    Line 1072: 2020-10-27 11:58:19 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1073: 2020-10-27 11:58:19 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.739548 seconds.
    Line 1074: 2020-10-27 11:58:21 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1075: 2020-10-27 11:58:21 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.021955 seconds.
    Line 1077: 2020-10-27 11:58:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
    Line 1078: 2020-10-27 11:58:25 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.322306 seconds.
    Line 1085: 2020-10-27 11:58:34 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
mastermc0 picture mastermc0 on 27 Oct 2020

@allenporter now that this has been running for 4 hours without any reboots (FYI, last reboot was around 8:15am and the time now is 12:15pm), my up to date logs are:

homeassistant.components.nest

No result

homeassistant.components.nest.sensor_sdm

No result

google.cloud.pubsub_v1

2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.dispatcher] Started helper thread Thread-CallbackRequestDispatcher
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.791155 seconds.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
2020-10-27 08:17:04 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Started helper thread Thread-Heartbeater
2020-10-27 08:17:10 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
2020-10-27 08:17:34 INFO (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Thread-Heartbeater exiting.

google.cloud.pubsub_v1.subscriber._protocol.leaser

2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current p99 value is 10 seconds.
2020-10-27 08:17:04 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.791155 seconds.
2020-10-27 08:17:04 DEBUG (MainThread) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Started helper thread Thread-LeaseMaintainer
2020-10-27 08:17:10 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
townsmcp picture townsmcp on 27 Oct 2020

I restarted a couple of times and observed the logs. I see the following right around the time it stops pulling messages.

2020-10-27 12:15:43 INFO (Thread-5) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 504 Deadline Exceeded

I don't see it reestablishing the stream. I see similar reports @ https://github.com/googleapis/python-pubsub/issues/78

william-shuman picture william-shuman on 27 Oct 2020

@william-shuman I didnt have that turned on for logging. Will do it now, reboot and report back if I get the same issue

townsmcp picture townsmcp on 27 Oct 2020

I restarted a couple of times and observed the logs. I see the following right around the time it stops pulling messages.

2020-10-27 12:15:43 INFO (Thread-5) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 504 Deadline Exceeded

I don't see it reestablishing the stream. I see similar reports @ googleapis/python-pubsub#78

Turned on debug logging and seeing this also approximately 10 minutes after the first message similar to the issue linked by @william-shuman.

mastermc0 picture mastermc0 on 27 Oct 2020

@mastermc0 what entry did you put into configuration.yaml? I added the following line but the logs dont show anything by the same name:

google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager: debug

townsmcp picture townsmcp on 27 Oct 2020

@townsmcp

My logger section is below. I seem to be struggling to get the format to display correctly but you get the idea.

logger:
  default: info
  logs:
    homeassistant.components.nest: debug
    homeassistant.components.nest.sensor_sdm: debug
    google.cloud.pubsub_v1: debug
    google.cloud.pubsub_v1.subscriber._protocol.leaser: debug
    google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager: debug
mastermc0 picture mastermc0 on 27 Oct 2020
👍1

@mastermc0 thank you. Seems like I had that setup already (see below) which is odd, I havent had a google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager appear in logs.

logger:
  default: info
  logs:
    homeassistant.core: debug
    # Nest SDM Integration logging #
    homeassistant.components.nest: debug
    homeassistant.components.nest.sensor_sdm: debug
    google.cloud.pubsub_v1: debug
    google.cloud.pubsub_v1.subscriber._protocol.leaser: debug
    google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager: debug
townsmcp picture townsmcp on 27 Oct 2020

I'm guessing this is the google_pubsub integration requirement (https://github.com/home-assistant/core/blob/6a67d29a2805483bb37a2a800602f0a906764a2a/requirements_all.txt#L677) interfering with the one for your library, can you add the google_pubsub integration, restart and see if you can reproduce it then?

william-shuman picture william-shuman on 27 Oct 2020

I'm guessing this is the google_pubsub integration requirement (

https://github.com/home-assistant/core/blob/6a67d29a2805483bb37a2a800602f0a906764a2a/requirements_all.txt#L677

) interfering with the one for your library, can you add the google_pubsub integration, restart and see if you can reproduce it then?

@william-shuman not sure if this was directed at @townsmcp or myself but if I add the google_pubsub integrations I still see the errors coming out in the same way as without that integration.

    Line 553: 2020-10-27 18:36:06 DEBUG (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Scheduling callbacks for 1 messages.
    Line 554: 2020-10-27 18:36:06 DEBUG (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Sent request(s) over unary RPC.
    Line 559: 2020-10-27 18:36:07 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Sent request(s) over unary RPC.
    Line 1360: 2020-10-27 18:46:03 INFO (Thread-8) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 504 Deadline Exceeded
mastermc0 picture mastermc0 on 27 Oct 2020

@william-shuman and @mastermc0 stupid question, but how do I add that? Is it just a line to configuration.yaml?

townsmcp picture townsmcp on 27 Oct 2020

It wasn't directed at either of you, but at the maintainer. I'm guessing both of you are running in a container so that is already added as it looks like the docker image does an install on on the requirements explicitly, which is different then what a python virtual environment install does.

william-shuman picture william-shuman on 27 Oct 2020
👍1

@william-shuman yep, I鈥檓 running on an RPI 4 so it鈥檚 containered. Thanks

townsmcp picture townsmcp on 27 Oct 2020

@william-shuman I鈥檓 running in a Docker container on an Ubuntu host so containered also.

mastermc0 picture mastermc0 on 27 Oct 2020

@allenporter it looks like the container does a install of requirements_all.txt which will end up with the following:
google_cloud_pubsub-0.39.1
google_api_core-1.23.0

Because of that we are hitting these old bugs. I'm not sure how home assistant deals with these differences in dependencies between integrations, but because the google_pubsub dependency declares google-cloud-pubsub==0.39.1 that is the version we get with the container. Could the google-cloud-pubsub dependency be bumped to get around these old bugs?

william-shuman picture william-shuman on 27 Oct 2020

FWIW - I'm running the -core distribution packages and have the following Google components installed in ~/homeassistant/lib/python3.8/site-packages/:
google_api_core-1.23.0
google_auth-1.22.0
google_auth_oauthlib-0.4.1
google_cloud_pubsub-2.1.0
google_nest_sdm-0.1.6
googleapis_common_protos-1.52.0

Frobitz66 picture Frobitz66 on 28 Oct 2020

Thanks all, this is really helpful. The underlying python library for SDM python-google-nest-sdm requires google-cloud-pubsub 2.1.0 in its setup.py

But then home assistant has in requirements_all.txt:

# homeassistant.components.google_pubsub
google-cloud-pubsub==0.39.1

Which implies that the google_pubsub is pinned to an old version.

When I test this locally, i'm using a developer environment:

$ script/setup
$ source venv/bin/activate
(venv) $ pip3 freeze | grep pubsub
google-cloud-pubsub==2.1.0

So that is getting the version I was expecting.

Perhaps in order to fix this, what we want to do is move the google_pubsub integration to the latest version of google pubsub. I can investigate this, unless someone gets to it first.

allenporter picture allenporter on 28 Oct 2020

I'm running your latest PR for the cameras (https://github.com/home-assistant/core/pull/42556) , after ~ 4 minutes it stops running and I get this error. Could this be related to the pubsub version? Or is this another issue?

2020-11-03 08:20:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.398273 seconds.
2020-11-03 08:20:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:39 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 6.800304 seconds.
2020-11-03 08:20:46 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:46 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.161205 seconds.
2020-11-03 08:20:48 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
2020-11-03 08:20:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:51 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.228414 seconds.
2020-11-03 08:20:52 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:52 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.923764 seconds.
2020-11-03 08:20:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:53 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.971971 seconds.
2020-11-03 08:20:55 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:20:55 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.976969 seconds.
2020-11-03 08:21:00 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:21:00 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.647169 seconds.
2020-11-03 08:21:02 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:21:02 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.327773 seconds.
2020-11-03 08:21:07 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:21:07 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 4.091630 seconds.
2020-11-03 08:21:11 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-03 08:21:11 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 6.059357 seconds.
2020-11-03 08:21:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139703323341056] Error handling message: Unknown error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/decorators.py", line 18, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/src/homeassistant/homeassistant/components/camera/__init__.py", line 592, in ws_camera_stream
    source = await camera.stream_source()
  File "/config/custom_components/nest/camera_sdm.py", line 102, in stream_source
    new_stream = await self._stream.extend_rtsp_stream()
  File "/usr/local/lib/python3.8/site-packages/google_nest_sdm/camera_traits.py", line 86, in extend_rtsp_stream
    resp.raise_for_status()
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client_reqrep.py", line 941, in raise_for_status
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message='Bad Request', url=URL('https://smartdevicemanagement.googleapis.com/v1/enterprises/XXXXXX-63f6-46a0-8c2a-7c8890d13546/devices/XXXXXXXXXfL1O57JXge-Zwpzf8fXdMsTtpnv_smNTA_8sytnm6xc9J2Qq0FvSFGKt2KWf3Tzwc_HVy4IIkj0hvIgMxe2V:executeCommand')
2020-11-03 08:21:15 ERROR (MainThread) [aiohttp.server] Error handling request
mike9011 picture mike9011 on 3 Nov 2020

Thanks for the report. This seems separate to me since nothing in the extend stream rox comes from the pubsub feed. I will investigate, though if you'd like to track it then maybe a separate issue would be best.

allenporter picture allenporter on 3 Nov 2020
👍1

I'm still seeing the Nest integration eventually stop pulling messages on the 0.118.0.dev20201107 container. Now I'm seeing this happen after 1 hour which seems like a token refresh issue.

2020-11-07 14:31:04 DEBUG (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Processing 1 received message(s), currently on hold 0 (bytes 0).
2020-11-07 14:31:04 DEBUG (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Exception while sending unary RPC. This is typically non-fatal as stream requests are best-effort.
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 57, in error_remapped_callable
return callable_(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 826, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 729, in _end_unary_response_blocking
raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
status = StatusCode.UNAUTHENTICATED
details = "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project."
debug_error_string = "{"created":"@1604759464.918513627","description":"Error received from peer ipv4:64.233.177.95:443","file":"src/core/lib/surface/call.cc","file_line":1061,"grpc_message":"Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.","grpc_status":16}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 417, in send
self._send_unary_request(request)
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 401, in _send_unary_request
self._client.modify_ack_deadline(
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/_gapic.py", line 40, in <lambda>
fx = lambda self, *a, **kw: wrapped_fx(self.api, *a, **kw) # noqa
File "/usr/local/lib/python3.8/site-packages/google/pubsub_v1/services/subscriber/client.py", line 823, in modify_ack_deadline
rpc(
File "/usr/local/lib/python3.8/site-packages/google/api_core/gapic_v1/method.py", line 145, in __call__
return wrapped_func(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 281, in retry_wrapped_func
return retry_target(
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 184, in retry_target
return target()
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 59, in error_remapped_callable
six.raise_from(exceptions.from_grpc_error(exc), exc)
File "<string>", line 3, in raise_from
google.api_core.exceptions.Unauthenticated: 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:04 DEBUG (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Released held message, scheduling callback for it, still on hold 0 (bytes 0).
2020-11-07 14:31:04 DEBUG (ThreadPoolExecutor-ThreadScheduler_1) [homeassistant.components.nest] Update ab1287a3-fc4c-4601-bdbf-8d6d1724fd8e @ 2020-11-07 14:31:03.164000+00:00
2020-11-07 14:31:04 DEBUG (ThreadPoolExecutor-ThreadScheduler_1) [homeassistant.components.nest] Event Update dict_keys(['sdm.devices.events.CameraMotion.Motion'])
2020-11-07 14:31:04 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.dispatcher] Handling 1 batched requests
2020-11-07 14:31:05 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Exception while sending unary RPC. This is typically non-fatal as stream requests are best-effort.
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 57, in error_remapped_callable
return callable_(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 826, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 729, in _end_unary_response_blocking
raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
status = StatusCode.UNAUTHENTICATED
details = "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project."
debug_error_string = "{"created":"@1604759465.049155569","description":"Error received from peer ipv4:64.233.177.95:443","file":"src/core/lib/surface/call.cc","file_line":1061,"grpc_message":"Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.","grpc_status":16}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 417, in send
self._send_unary_request(request)
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 388, in _send_unary_request
self._client.acknowledge(
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/_gapic.py", line 40, in <lambda>
fx = lambda self, *a, **kw: wrapped_fx(self.api, *a, **kw) # noqa
File "/usr/local/lib/python3.8/site-packages/google/pubsub_v1/services/subscriber/client.py", line 909, in acknowledge
rpc(
File "/usr/local/lib/python3.8/site-packages/google/api_core/gapic_v1/method.py", line 145, in __call__
return wrapped_func(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 281, in retry_wrapped_func
return retry_target(
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 184, in retry_target
return target()
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 59, in error_remapped_callable
six.raise_from(exceptions.from_grpc_error(exc), exc)
File "<string>", line 3, in raise_from
google.api_core.exceptions.Unauthenticated: 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.484448 seconds.
2020-11-07 14:31:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:09 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 5.058269 seconds.
2020-11-07 14:31:14 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:14 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 1.491014 seconds.
2020-11-07 14:31:15 DEBUG (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Sent heartbeat.
2020-11-07 14:31:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:16 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.383541 seconds.
2020-11-07 14:31:18 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:18 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 7.994564 seconds.
2020-11-07 14:31:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 0.233641 seconds.
2020-11-07 14:31:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:26 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.545091 seconds.
2020-11-07 14:31:35 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2020-11-07 14:31:35 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 8.472114 seconds.
2020-11-07 14:31:41 INFO (Thread-6) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 500 Received RST_STREAM with error code 2
2020-11-07 14:31:41 INFO (Thread-6) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 500 Received RST_STREAM with error code 2
2020-11-07 14:31:41 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 500 Received RST_STREAM with error code 2
2020-11-07 14:31:41 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed recoverable stream error 500 Received RST_STREAM with error code 2
2020-11-07 14:31:41 INFO (Thread-6) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:41 INFO (Thread-6) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-recoverable stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:41 INFO (Thread-6) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] RPC termination has signaled streaming pull manager shutdown.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping consumer.
2020-11-07 14:31:41 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:41 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-recoverable stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping scheduler.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping leaser.
2020-11-07 14:31:41 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping dispatcher.
2020-11-07 14:31:41 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.helper_threads] Exiting the QueueCallbackWorker.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping heartbeater.
2020-11-07 14:31:41 INFO (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Thread-Heartbeater exiting.
2020-11-07 14:31:41 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Finished stopping manager.
william-shuman picture william-shuman on 7 Nov 2020

Thanks. I haven't run into this issue myself yet but know what the cause might be.

Right now the subscriber is just passed an access token but not a refresh token.

allenporter picture allenporter on 7 Nov 2020

Right now the subscriber is just passed an access token but not a refresh token.

That would explain what I'm seeing. The access token is only valid for one hour [1]. I'm interested in how you haven't run into this, have you had the integration running for more then an hour?

  1. https://developers.google.com/nest/device-access/authorize#:~:text=Access%20tokens%20for%20the%20SDM,to%20get%20a%20new%20one.
william-shuman picture william-shuman on 7 Nov 2020

Yeah, apologies, I don't do this. I have 3 home assistant environments:

  • prod: running a "stable" home assistant that doesn't yet support nest that I use for automation in my house
  • dev: running a "latest" build (117 something), which still has the previous broken pubsub behavior due to having that very old pubsub subscriber (fixed in another issue)

For local development, I rely heavily on unit testing. I run a local HA instance for manual testing, but typically just leave it running for 5 minutes while trying out a feature (why I didn't notice pubsub was busted after 10 minutes before) or ~15 minutes to test out the stream URL refresh issues.

I'll exercise it a bit better.

allenporter picture allenporter on 7 Nov 2020

(I run my two long running instances on kubernetes. I don't yet know how to build a helm/docker images from a local github repo, so if i figure that out i can test this better and run my "dev" instance at HEAD)

allenporter picture allenporter on 7 Nov 2020

I believe the fix will be to pass some additional parameters to the Creds object created in api.py -- in particular it just accepts a token right now, but likely also needs the other params to Credentials needed to refresh. Most of these either come from oauth implementation created in __init__.py or from the OAuthSession object. This should be straight forward, but i may want something elegant for code reuse across the two oauth implementations.

allenporter picture allenporter on 7 Nov 2020

Thanks for the explanation, this was really helpful. I'll try to start digging into the code this week.

william-shuman picture william-shuman on 8 Nov 2020

Lets keep discussing in https://github.com/home-assistant/core/issues/42947 since that actively captures the problem in a new issue.

allenporter picture allenporter on 8 Nov 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

neonandu picture neonandu  路  3Comments
sibbl picture sibbl  路  3Comments
MartinHjelmare picture MartinHjelmare  路  3Comments
Elmardus picture Elmardus  路  3Comments
Konstigt picture Konstigt  路  3Comments