Timeout communicating with habackup.io

morten-thomassen commented 2 years ago

Description:

Couldn't Refresh Google Drive Credentials The addon was unable to refresh your credentials with Google Drive. When it tried, https://habackup.io said: Timed out communicating with habackup.io

Since the latest update, I have been getting the above message
Neither hitting the sync button nor re-authenticating seems to help.

Addon version: 0.106.2 Home Assistant Version: 2022.3.8 Supervisor Version: 2022.03.5 Supervisor Channel: stable Hassos Version: 7.6 Docker Version: 20.10.9 Architecture: aarch64 Machine: raspberrypi4-64 Date: 2022-04-02T12:58:00.549067+00:00 Timezone: Europe/London Failure Time: 2022-04-02T11:58:43.709438+00:00 Last Good Sync: 2022-04-02T11:58:22.451674+00:00

Exception:


  addon/backup/model/coordinator.py:176 (_sync)
  addon/backup/model/model.py:167 (sync)
  addon/backup/model/model.py:275 (_syncBackups)
  addon/backup/drive/drivesource.py:100 (get)
  addon/backup/drive/drivesource.py:219 (getFolderId)
  addon/backup/drive/folderfinder.py:65 (get)
  addon/backup/drive/folderfinder.py:117 (_readFolderId)
  addon/backup/drive/folderfinder.py:158 (_verify)
  addon/backup/drive/driverequests.py:148 (get)
  addon/backup/drive/driverequests.py:339 (retryRequest)
  addon/backup/drive/driverequests.py:92 (_getHeaders)
  addon/backup/drive/driverequests.py:137 (getToken)
  addon/backup/creds/exchanger.py:85 (refresh)
  addon/backup/creds/exchanger.py:158 (_refresh_default)
backup.exceptions.exceptions.CredRefreshMyError: Timed out communicating with habackup.io

Backups:

 {
    "HomeAssistant": {
        "backups": 1,
        "retained": 0,
        "deletable": 1,
        "name": "HomeAssistant",
        "title": "Home Assistant",
        "latest": "2022-03-30T08:15:03Z",
        "max": 1,
        "enabled": true,
        "icon": "home-assistant",
        "ignored": 0,
        "size": "54.9 MB",
        "ignored_size": "0.0 B",
        "free_space": "122.3 GB"
    },
    "GoogleDrive": {
        "backups": 4,
        "retained": 0,
        "deletable": 4,
        "name": "GoogleDrive",
        "title": "Google Drive",
        "latest": "2022-03-30T08:15:03Z",
        "max": 4,
        "enabled": true,
        "icon": "google-drive",
        "ignored": 0,
        "size": "201.0 MB",
        "ignored_size": "0.0 B",
        "free_space": "14.8 GB"
    }
}

Config:

 {
    "Setting.MAX_BACKUPS_IN_HA": 1,
    "Setting.DAYS_BETWEEN_BACKUPS": 4.0,
    "Setting.BACKUP_NAME": "REDACTED",
    "Setting.BACKUP_TIME_OF_DAY": "04:00",
    "Setting.BACKUP_PASSWORD": "REDACTED",
    "Setting.SEND_ERROR_REPORTS": true,
    "Setting.MAX_SYNC_INTERVAL_SECONDS": 18000.0
}

Addon Logs:

 04-02 11:25:04 INFO [backup.model.coordinator] Syncing Backups
04-02 11:25:04 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/supervisor/info
04-02 11:25:04 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/backups
04-02 11:25:04 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
04-02 11:25:14 WARNING [backup.creds.exchanger] Timed out communicating with token1.habackup.io, trying alternate server(s)...
04-02 11:25:25 WARNING [backup.creds.exchanger] Timed out communicating with habackup.io, trying alternate server(s)...
04-02 11:25:25 ERROR [backup.creds.exchanger] Unable to refresh credentials with Google Drive
04-02 11:25:25 ERROR [backup.model.coordinator] Couldn't refresh Google Drive credentials because: Timed out communicating with habackup.io
04-02 11:25:25 INFO [backup.model.coordinator] I'll try again in an hour
04-02 11:29:58 INFO [backup.drive.drivesource] Saving new Google Drive credentials
04-02 11:29:59 DEBUG [backup.model.syncer] Sync requested by GoogleDrive
04-02 11:29:59 INFO [backup.model.coordinator] Syncing Backups
04-02 11:29:59 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/supervisor/info
04-02 11:29:59 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/backups
04-02 11:29:59 DEBUG [backup.drive.driverequests] Making Google Drive request: https://www.googleapis.com/drive/v3/files/1sr1nOAhx27Mqg1YFv9WuhZi-TGEHHqB_/?fields=id%2Cname%2CappProperties%2Csize%2Ctrashed%2CmimeType%2CmodifiedTime%2Ccapabilities%2Cparents%2CdriveId&supportsAllDrives=true
04-02 11:58:22 DEBUG [backup.creds.driverequester] Ran into trouble reaching Google Drive's servers.  We'll use alternate DNS servers on the next attempt.
04-02 11:58:22 ERROR [backup.model.coordinator] Unable to connect to www.googleapis.com
04-02 11:58:22 INFO [backup.model.coordinator] I'll try again in an hour
04-02 11:58:23 INFO [backup.debugworker] Sending error report (see settings to disable)
04-02 12:58:22 DEBUG [backup.model.syncer] Sync requested by Coordinator
04-02 12:58:22 INFO [backup.model.coordinator] Syncing Backups
04-02 12:58:22 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/supervisor/info
04-02 12:58:22 DEBUG [backup.ha.harequests] Making Hassio request: http://supervisor/backups
04-02 12:58:22 DEBUG [backup.drive.driverequests] Requesting refreshed Google Drive credentials
04-02 12:58:32 WARNING [backup.creds.exchanger] Timed out communicating with token1.habackup.io, trying alternate server(s)...
04-02 12:58:43 WARNING [backup.creds.exchanger] Timed out communicating with habackup.io, trying alternate server(s)...
04-02 12:58:43 ERROR [backup.creds.exchanger] Unable to refresh credentials with Google Drive
04-02 12:58:43 ERROR [backup.model.coordinator] Couldn't refresh Google Drive credentials because: Timed out communicating with habackup.io
04-02 12:58:43 INFO [backup.model.coordinator] I'll try again in an hour
04-02 12:58:47 INFO [backup.debugworker] Sending error report (see settings to disable)

Supervisor Logs:

 [31m22-04-02 12:39:26 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-95905' coro=<Repository.update() done, defined at /usr/src/supervisor/supervisor/store/repository.py:106> exception=StoreJobError("'GitRepo.pull' blocked from execution, no supervisor internet connection")>[0m
Traceback (most recent call last):
  File "/usr/src/supervisor/supervisor/store/repository.py", line 110, in update
    await self.git.pull()
  File "/usr/src/supervisor/supervisor/jobs/decorator.py", line 87, in wrapper
    raise self.on_condition(error_msg, _LOGGER.warning) from None
supervisor.exceptions.StoreJobError: 'GitRepo.pull' blocked from execution, no supervisor internet connection
[32m22-04-02 12:39:27 INFO (MainThread) [supervisor.jobs] 'StoreManager.update_repositories' blocked from execution, no supervisor internet connection[0m
[32m22-04-02 12:39:27 INFO (MainThread) [supervisor.store] Loading add-ons from store: 160 all - 0 new - 0 remove[0m
[32m22-04-02 12:39:53 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token[0m
[32m22-04-02 12:58:22 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/info access from cebe7a76_hassio_google_drive_backup[0m
[32m22-04-02 12:58:22 INFO (MainThread) [supervisor.api.middleware.security] /backups access from cebe7a76_hassio_google_drive_backup[0m
[32m22-04-02 13:09:54 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state CoreState.RUNNING[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.SECURITY/ContextType.CORE[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.FREE_SPACE/ContextType.SYSTEM[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.PLUGIN[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.PWNED/ContextType.ADDON[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.jobs] 'CheckAddonPwned.run_check' blocked from execution, no supervisor internet connection[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.CORE[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.checks.base] Run check for IssueType.TRUST/ContextType.SUPERVISOR[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.check] System checks complete[0m
[32m22-04-02 13:37:44 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state CoreState.RUNNING[0m
[32m22-04-02 13:37:45 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete[0m
[32m22-04-02 13:37:45 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state CoreState.RUNNING[0m
[32m22-04-02 13:37:45 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete[0m
[32m22-04-02 13:39:54 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token[0m
[32m22-04-02 13:58:00 INFO (MainThread) [supervisor.api.middleware.security] /supervisor/logs access from cebe7a76_hassio_google_drive_backup[0m

Home Assistant Core Logs:

     _, protocol = await loop.create_connection(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1056, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1041, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 955, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 502, in sock_connect
    return await fut
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 537, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('192.168.1.18', 6668)[0m
[31m2022-04-02 13:59:35 ERROR (MainThread) [custom_components.localtuya.common] [068...e91] Connect to 192.168.1.17 failed
Traceback (most recent call last):
  File "/config/custom_components/localtuya/common.py", line 145, in _make_connection
    self._interface = await pytuya.connect(
  File "/config/custom_components/localtuya/pytuya/__init__.py", line 669, in connect
    _, protocol = await loop.create_connection(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1056, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1041, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 955, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 502, in sock_connect
    return await fut
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 537, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('192.168.1.17', 6668)[0m

sabeechen commented 2 years ago

Sorry this took me a while to get back to you one, I've been preoccupied with other demands.

Habackup.io is the domain I maintain to serve refreshed Google Drive credentials for the addon. In the logs I can see that it timed out attempting to reach both that domain and the backup domain (token1.habackup.io). For redundancy purposes these two domains are hosted on seoarate cloud providers, and it is very unlikely you'd be unable to communicate with both of them at the same time.

Are you confident the machine didn't just lose internet connectivity for a period of time, and does the problem still persist right now? Normally I'd recommend reauthorizing, thank you for trying that. Could I have you try:

Restart the host machine. Home Assistant does some tricky DNS caching, and I know that in rare cases it gets messed up and causes communication errors. Restarting the machine can clear that cache.
Could you try authenticating with Google using a new Google account (they're quick to create). This would determine if there is something wrong with your Google account, which is also rare but does happen sometimes.

morten-thomassen commented 2 years ago

Actually, it may well have been connectivity. We had massive dropouts last week, finally getting better this weekend.

I have been installing all updates as they become available (core, os, supervisor, various addons), and even done a host restart, and between all of this, and the internet improving, I am no longer seeing the error!

... Which is great news, and we can close this ticket.

Obviously, it would have been more satisfying to know which of the above did the trick, but I certainly know what to try should it ever recur.

Thank you!

sabeechen / hassio-google-drive-backup