mirror of
https://github.com/jwoglom/tconnectsync.git
synced 2026-08-24 02:34:11 -05:00
Harden autoupdate against transient errors instead of exiting
get() retries only HTTP 401 and 500, so any other API error propagates out of the autoupdate loop and exits the process. When Tandem retired the reportsfacade endpoints and pumpeventmetadata began returning 404 (#146), a container with a restart policy would crash-loop. That is the worst possible response to an API outage: the credentials cache dies with the process, so every restart performs a full login against sso.tandemdiabetes.com. In my EU deployment that was a fresh login roughly every two minutes for hours from a single IP, which seems a good way to earn a WAF ban while already broken. Transient network errors (DNS failures, timeouts, mid-stream disconnects, urllib3 retry-budget exhaustion) have the same problem. This keeps both failure families inside the loop and backs off exponentially: 30s doubling to a cap of AUTOUPDATE_DEFAULT_SLEEP_SECONDS (300s default), reset on any successful poll. The cap reuses the existing poll interval, so a failing API is never contacted more often than a healthy one. After three consecutive failures the log escalates from WARNING to ERROR. Staying alive forever would make a real outage silent on deployments whose only alarm is the container dying, so after AUTOUPDATE_API_FAILURE_MINUTES (default 45) of unbroken failure the process gives up and exits non-zero. That is roughly one restart per hour during a genuine outage instead of one every two minutes, while short blips stay silent. Set 0 to disable. This is deliberately not gated on AUTOUPDATE_RESTART_ON_FAILURE, which covers the pump-not-uploading watchdog where restarting achieves nothing (as the existing TODO notes) and which many users therefore disable. An unreachable API is a different failure and gets its own knob. ApiLoginException stays fatal: bad credentials are not transient, and retrying them in-process would hammer the login endpoint with attempts that cannot succeed. Also included: - A defensive clamp so a negative rolling-average entry can never reach time.sleep() and crash with ValueError. - Tests covering the backoff sequence, reset-on-success, the sustained-failure exit, the opt-out, and that login failures and programming errors still propagate. - README documentation for all nine AUTOUPDATE_* variables, none of which were documented outside secret.py.
This commit is contained in:
xannasavin
James Woglom
@@ -381,6 +381,36 @@ An example `run.sh` if you built tconnectsync locally:
|
||||
docker run tconnectsync --auto-update
|
||||
```
|
||||
|
||||
#### Tuning Auto-Update
|
||||
|
||||
These optional environment variables control how `--auto-update` polls and how
|
||||
it behaves when things go wrong. The defaults are sensible; you generally only
|
||||
need these if you are seeing too many (or too few) restarts.
|
||||
|
||||
| Variable | Default | What it does |
|
||||
| --- | --- | --- |
|
||||
| `AUTOUPDATE_DEFAULT_SLEEP_SECONDS` | `300` | Poll interval when no better estimate is available. Also the ceiling for the retry backoff below. |
|
||||
| `AUTOUPDATE_MAX_SLEEP_SECONDS` | `1500` | Upper bound on the adaptive poll interval, regardless of how rarely new data appears. |
|
||||
| `AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS` | `60` | How long to wait when new data is overdue based on the pump's previous cadence. |
|
||||
| `AUTOUPDATE_USE_FIXED_SLEEP` | `false` | Set true to always sleep `AUTOUPDATE_DEFAULT_SLEEP_SECONDS` instead of adapting to the pump's observed upload cadence. |
|
||||
| `AUTOUPDATE_API_FAILURE_MINUTES` | `45` | Exit with a non-zero code after this many minutes of unbroken API/network failure, so your container platform restarts tconnectsync and can alert you. Set `0` to never exit. |
|
||||
| `AUTOUPDATE_NO_DATA_FAILURE_MINUTES` | `180` | Log an error if the pump has not reported new events for this long. Usually means the pump simply is not uploading. |
|
||||
| `AUTOUPDATE_FAILURE_MINUTES` | `75` | Log an error if events are appearing but no data has synced successfully for this long. |
|
||||
| `AUTOUPDATE_RESTART_ON_FAILURE` | `false` | Whether the two watchdogs above also exit non-zero. Independent of `AUTOUPDATE_API_FAILURE_MINUTES`. |
|
||||
| `AUTOUPDATE_MAX_LOOP_INVOCATIONS` | `-1` | Stop after this many poll cycles. `-1` means run forever; mainly useful for testing. |
|
||||
|
||||
**On failures and restarts.** Transient errors (DNS blips, timeouts, HTTP 404/502/503
|
||||
from Tandem) do not crash tconnectsync. It retries with a growing backoff — 30s,
|
||||
60s, 120s, 240s, then holding at `AUTOUPDATE_DEFAULT_SLEEP_SECONDS` — and resets
|
||||
as soon as a poll succeeds. Staying in-process matters: an exit discards the
|
||||
cached credentials, so a restart loop means a fresh login on every attempt,
|
||||
which risks tripping Tandem's rate limiting.
|
||||
|
||||
Only once the API has been failing continuously for `AUTOUPDATE_API_FAILURE_MINUTES`
|
||||
does tconnectsync give up and exit, so that a genuine outage surfaces (roughly one
|
||||
restart per hour) instead of disappearing into an endless quiet retry. Invalid
|
||||
credentials are never retried — they exit immediately, since retrying cannot help.
|
||||
|
||||
### Running with Cron
|
||||
|
||||
If you choose not to run tconnectsync with `--auto-update` continuously,
|
||||
|
||||
@@ -73,6 +73,11 @@ AUTOUPDATE_USE_FIXED_SLEEP = get_bool('AUTOUPDATE_USE_FIXED_SLEEP', 'false')
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES = get_number('AUTOUPDATE_NO_DATA_FAILURE_MINUTES', '180') # 3 hours
|
||||
AUTOUPDATE_FAILURE_MINUTES = get_number('AUTOUPDATE_FAILURE_MINUTES', '75') # 75 minutes
|
||||
AUTOUPDATE_RESTART_ON_FAILURE = get_bool('AUTOUPDATE_RESTART_ON_FAILURE', 'false')
|
||||
# Give up and exit non-zero after this many minutes of unbroken API/network
|
||||
# failure, so the container platform notices (and, if configured, notifies).
|
||||
# Distinct from AUTOUPDATE_RESTART_ON_FAILURE, which covers the pump not
|
||||
# uploading -- a case where restarting achieves nothing. Set 0 to never exit.
|
||||
AUTOUPDATE_API_FAILURE_MINUTES = get_number('AUTOUPDATE_API_FAILURE_MINUTES', '45') # 45 minutes
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS = get_number('AUTOUPDATE_MAX_LOOP_INVOCATIONS', '-1')
|
||||
|
||||
NIGHTSCOUT_PROFILE_UPLOAD_MODE = get_one_of('NIGHTSCOUT_PROFILE_UPLOAD_MODE', 'add', ['add', 'replace'])
|
||||
|
||||
@@ -3,7 +3,9 @@ import logging
|
||||
import datetime
|
||||
import sys
|
||||
import arrow
|
||||
import requests
|
||||
|
||||
from ...api.common import ApiException, ApiLoginException
|
||||
from ...features import DEFAULT_FEATURES
|
||||
from ...api.tandemsource import naive_local_to_utc
|
||||
from .process import ProcessTimeRange
|
||||
@@ -11,11 +13,21 @@ from .choose_device import ChooseDevice
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
# Shortest wait after a failed poll. Doubles per consecutive failure, capped at
|
||||
# AUTOUPDATE_DEFAULT_SLEEP_SECONDS (5 min by default): 30, 60, 120, 240, 300...
|
||||
RETRY_INITIAL_SLEEP_SECONDS = 30
|
||||
|
||||
# Consecutive failures before the retry log line escalates from WARNING to
|
||||
# ERROR, so a sustained outage doesn't hide quietly inside the backoff.
|
||||
RETRY_ESCALATE_AFTER_FAILURES = 3
|
||||
|
||||
class TandemSourceAutoupdate:
|
||||
"""Wrap access to secrets for easier testing."""
|
||||
def __init__(self, secret):
|
||||
self.secret = secret
|
||||
self.autoupdate_invocations = 0
|
||||
self.consecutive_failures = 0
|
||||
self.first_failure_time = None
|
||||
self.last_max_date_with_events = None
|
||||
self.last_event_time = 0
|
||||
self.last_attempt_time = 0
|
||||
@@ -39,127 +51,227 @@ class TandemSourceAutoupdate:
|
||||
self.autoupdate_start = time.time()
|
||||
|
||||
while True:
|
||||
logger.debug("autoupdate loop")
|
||||
now = time.time()
|
||||
try:
|
||||
logger.debug("autoupdate loop")
|
||||
now = time.time()
|
||||
|
||||
time_end = datetime.datetime.now()
|
||||
time_start = time_end - datetime.timedelta(days=1)
|
||||
time_end = datetime.datetime.now()
|
||||
time_start = time_end - datetime.timedelta(days=1)
|
||||
|
||||
tconnectDevice = ChooseDevice(self.secret, tconnect).choose()
|
||||
tconnectDevice = ChooseDevice(self.secret, tconnect).choose()
|
||||
|
||||
event_seqnum = None
|
||||
cur_max_date_with_events = arrow.get(naive_local_to_utc(tconnectDevice['maxDateOfEvents'])).float_timestamp
|
||||
if not self.last_max_date_with_events or cur_max_date_with_events > self.last_max_date_with_events:
|
||||
logger.info('New reported tandemsource data. (cur_max_date: %s last_max_date: %s)' % (cur_max_date_with_events, self.last_max_date_with_events))
|
||||
event_seqnum = None
|
||||
cur_max_date_with_events = arrow.get(naive_local_to_utc(tconnectDevice['maxDateOfEvents'])).float_timestamp
|
||||
if not self.last_max_date_with_events or cur_max_date_with_events > self.last_max_date_with_events:
|
||||
logger.info('New reported tandemsource data. (cur_max_date: %s last_max_date: %s)' % (cur_max_date_with_events, self.last_max_date_with_events))
|
||||
|
||||
if pretend:
|
||||
logger.info('Would update now if not in pretend mode')
|
||||
if pretend:
|
||||
logger.info('Would update now if not in pretend mode')
|
||||
else:
|
||||
added, event_seqnum = ProcessTimeRange(tconnect, nightscout, tconnectDevice, pretend, self.secret, features=features).process(time_start, time_end)
|
||||
logger.info('Added %d items from ProcessTimeRange' % added)
|
||||
self.last_successful_process_time_range = now
|
||||
|
||||
# Track the time it took to find a new event between runs,
|
||||
# but skip this calculation the first process cycle (since
|
||||
# we don't know at what exact point the event index changed)
|
||||
if self.last_event_seqnum:
|
||||
# A negative diff means the pump's previously-reported maxDateWithEvents
|
||||
# was in the future of wall-clock `now` — almost always a timezone /
|
||||
# clock-skew issue (e.g. pump timestamps tagged as UTC but actually
|
||||
# local time). Recording it would poison the rolling average and
|
||||
# eventually produce a negative sleep_secs that crashes time.sleep().
|
||||
diff = now - self.last_max_date_with_events
|
||||
if diff >= 0:
|
||||
self.time_diffs_between_updates.append(diff)
|
||||
logger.debug('Updating tracking of time since last update: %s' % self.time_diffs_between_updates)
|
||||
else:
|
||||
logger.warning(
|
||||
'Skipping negative time diff (%0.1fs) — likely pump clock skew or timezone mismatch' % diff
|
||||
)
|
||||
|
||||
# Mark the last event index uploaded from the pump and timestamp
|
||||
if event_seqnum:
|
||||
self.last_event_seqnum = event_seqnum
|
||||
self.last_event_time = now
|
||||
self.last_max_date_with_events = cur_max_date_with_events
|
||||
self.last_attempt_time = now
|
||||
self.time_diffs_between_attempts = []
|
||||
else:
|
||||
added, event_seqnum = ProcessTimeRange(tconnect, nightscout, tconnectDevice, pretend, self.secret, features=features).process(time_start, time_end)
|
||||
logger.info('Added %d items from ProcessTimeRange' % added)
|
||||
self.last_successful_process_time_range = now
|
||||
logger.info('No new reported tandemsource data. cur_max_date: %s (%s) last_event_time: %s (%s)' % (
|
||||
arrow.get(cur_max_date_with_events) if cur_max_date_with_events else None,
|
||||
'%dm ago' % ((now - cur_max_date_with_events)//60) if cur_max_date_with_events else None,
|
||||
arrow.get(self.last_event_time) if self.last_event_time else None,
|
||||
'%dm ago' % ((now - self.last_event_time)//60) if self.last_event_time else None
|
||||
))
|
||||
|
||||
# Track the time it took to find a new event between runs,
|
||||
# but skip this calculation the first process cycle (since
|
||||
# we don't know at what exact point the event index changed)
|
||||
if self.last_event_seqnum:
|
||||
self.time_diffs_between_updates.append(now - self.last_max_date_with_events)
|
||||
logger.debug('Updating tracking of time since last update: %s' % self.time_diffs_between_updates)
|
||||
# If we haven't seen the pump event index update in AUTOUPDATE_NO_DATA_FAILURE_MINUTES,
|
||||
# then trigger an error and potentially restart.
|
||||
# The most likely case here is that the pump isn't uploading right now.
|
||||
if self.last_event_time and (now - self.last_event_time) >= 60 * self.secret.AUTOUPDATE_NO_DATA_FAILURE_MINUTES:
|
||||
logger.error(AutoupdateNoEventIndexesDetectedError(
|
||||
"%s: No new data event indexes have been detected for %d minutes. " % (datetime.datetime.now(), (now - self.last_event_time)//60) +
|
||||
"New data might not be uploading."))
|
||||
|
||||
# Mark the last event index uploaded from the pump and timestamp
|
||||
if event_seqnum:
|
||||
self.last_event_seqnum = event_seqnum
|
||||
self.last_event_time = now
|
||||
self.last_max_date_with_events = cur_max_date_with_events
|
||||
self.last_attempt_time = now
|
||||
self.time_diffs_between_attempts = []
|
||||
else:
|
||||
logger.info('No new reported tandemsource data. cur_max_date: %s (%s) last_event_time: %s (%s)' % (
|
||||
arrow.get(cur_max_date_with_events) if cur_max_date_with_events else None,
|
||||
'%dm ago' % ((now - cur_max_date_with_events)//60) if cur_max_date_with_events else None,
|
||||
arrow.get(self.last_event_time) if self.last_event_time else None,
|
||||
'%dm ago' % ((now - self.last_event_time)//60) if self.last_event_time else None
|
||||
))
|
||||
# TODO: restarting doesn't really help anything here.
|
||||
# Should we notify the user?
|
||||
if self.secret.AUTOUPDATE_RESTART_ON_FAILURE:
|
||||
logger.error("Exiting with error code due to AUTOUPDATE_RESTART_ON_FAILURE")
|
||||
return 1
|
||||
|
||||
# If we haven't seen the pump event index update in AUTOUPDATE_NO_DATA_FAILURE_MINUTES,
|
||||
# then trigger an error and potentially restart.
|
||||
# The most likely case here is that the pump isn't uploading right now.
|
||||
if self.last_event_time and (now - self.last_event_time) >= 60 * self.secret.AUTOUPDATE_NO_DATA_FAILURE_MINUTES:
|
||||
logger.error(AutoupdateNoEventIndexesDetectedError(
|
||||
"%s: No new data event indexes have been detected for %d minutes. " % (datetime.datetime.now(), (now - self.last_event_time)//60) +
|
||||
"New data might not be uploading."))
|
||||
# Similarly, if we HAVE seen pump event indexes update but have not successfully
|
||||
# found any associated data updates from the tconnect API for AUTOUPDATE_NO_DATA_FAILURE_MINUTES,
|
||||
# trigger an error and potentially restart. This could either be a tconnectsync problem,
|
||||
# where we can see the indexes increasing, but it takes us until a period of no index
|
||||
# update to reach our AUTOUPDATE_FAILURE_MINUTES threshold; or, a side effect of the
|
||||
# above no indexes warning.
|
||||
elif self.last_successful_process_time_range and (now - self.last_successful_process_time_range) >= 60 * self.secret.AUTOUPDATE_FAILURE_MINUTES:
|
||||
logger.error(AutoupdateNoNewDataDetectedError(
|
||||
"%s: No new data has been detected via the API for %d minutes (last: %s). " % (datetime.datetime.now(), (now - self.last_successful_process_time_range)//60, self.last_successful_process_time_range) +
|
||||
"tconnectsync might not be functioning properly."))
|
||||
|
||||
# TODO: restarting doesn't really help anything here.
|
||||
# Should we notify the user?
|
||||
if self.secret.AUTOUPDATE_RESTART_ON_FAILURE:
|
||||
logger.error("Exiting with error code due to AUTOUPDATE_RESTART_ON_FAILURE")
|
||||
return 1
|
||||
if self.secret.AUTOUPDATE_RESTART_ON_FAILURE:
|
||||
logger.error("%s: Exiting with error code due to AUTOUPDATE_RESTART_ON_FAILURE" % datetime.datetime.now())
|
||||
return 1
|
||||
|
||||
# Similarly, if we HAVE seen pump event indexes update but have not successfully
|
||||
# found any associated data updates from the tconnect API for AUTOUPDATE_NO_DATA_FAILURE_MINUTES,
|
||||
# trigger an error and potentially restart. This could either be a tconnectsync problem,
|
||||
# where we can see the indexes increasing, but it takes us until a period of no index
|
||||
# update to reach our AUTOUPDATE_FAILURE_MINUTES threshold; or, a side effect of the
|
||||
# above no indexes warning.
|
||||
elif self.last_successful_process_time_range and (now - self.last_successful_process_time_range) >= 60 * self.secret.AUTOUPDATE_FAILURE_MINUTES:
|
||||
logger.error(AutoupdateNoNewDataDetectedError(
|
||||
"%s: No new data has been detected via the API for %d minutes (last: %s). " % (datetime.datetime.now(), (now - self.last_successful_process_time_range)//60, self.last_successful_process_time_range) +
|
||||
"tconnectsync might not be functioning properly."))
|
||||
# Track how long we've been retrying
|
||||
if self.last_attempt_time:
|
||||
self.time_diffs_between_attempts.append(now - self.last_attempt_time)
|
||||
|
||||
if self.secret.AUTOUPDATE_RESTART_ON_FAILURE:
|
||||
logger.error("%s: Exiting with error code due to AUTOUPDATE_RESTART_ON_FAILURE" % datetime.datetime.now())
|
||||
return 1
|
||||
self.last_attempt_time = now
|
||||
|
||||
# Track how long we've been retrying
|
||||
if self.last_attempt_time:
|
||||
self.time_diffs_between_attempts.append(now - self.last_attempt_time)
|
||||
# If it's been 3 loops since the last time we found new data,
|
||||
# then we're not in sync with the rate at which pump data is being
|
||||
# uploaded, so
|
||||
if len(self.time_diffs_between_attempts) >= 3:
|
||||
# The pump hasn't sent us data that, based on previous cadence, we were expecting
|
||||
logger.warning(AutoupdateNoIndexChangeWarning("Sleeping %d seconds after unexpected no index change based on previous cadence. (New data might be delayed.)" %
|
||||
int(self.secret.AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS)))
|
||||
|
||||
self.last_attempt_time = now
|
||||
logger.debug("Last event time: %s, time diffs between attempts: %s" % (self.last_event_time, self.time_diffs_between_attempts))
|
||||
|
||||
# If it's been 3 loops since the last time we found new data,
|
||||
# then we're not in sync with the rate at which pump data is being
|
||||
# uploaded, so
|
||||
if len(self.time_diffs_between_attempts) >= 3:
|
||||
# The pump hasn't sent us data that, based on previous cadence, we were expecting
|
||||
logger.warning(AutoupdateNoIndexChangeWarning("Sleeping %d seconds after unexpected no index change based on previous cadence. (New data might be delayed.)" %
|
||||
int(self.secret.AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS)))
|
||||
# The API answered, so any prior outage is over.
|
||||
self.consecutive_failures = 0
|
||||
self.first_failure_time = None
|
||||
|
||||
logger.debug("Last event time: %s, time diffs between attempts: %s" % (self.last_event_time, self.time_diffs_between_attempts))
|
||||
time.sleep(self.secret.AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS)
|
||||
|
||||
time.sleep(self.secret.AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS)
|
||||
# Since we bail early, update the invocations count and potentially exit after sleeping.
|
||||
self.autoupdate_invocations += 1
|
||||
if self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS > 0 and self.autoupdate_invocations >= self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS:
|
||||
return 0
|
||||
|
||||
# Since we bail early, update the invocations count and potentially exit after sleeping.
|
||||
self.autoupdate_invocations += 1
|
||||
if self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS > 0 and self.autoupdate_invocations >= self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS:
|
||||
return 0
|
||||
continue
|
||||
|
||||
continue
|
||||
# The API answered, so any prior outage is over.
|
||||
self.consecutive_failures = 0
|
||||
self.first_failure_time = None
|
||||
|
||||
sleep_secs = self.secret.AUTOUPDATE_DEFAULT_SLEEP_SECONDS
|
||||
sleep_secs = self.secret.AUTOUPDATE_DEFAULT_SLEEP_SECONDS
|
||||
|
||||
# Sleep for a rolling average of time between updates
|
||||
if self.secret.AUTOUPDATE_USE_FIXED_SLEEP != 1:
|
||||
logger.debug("Time diffs between updates: %s" % self.time_diffs_between_updates)
|
||||
# Sleep for a rolling average of time between updates
|
||||
if self.secret.AUTOUPDATE_USE_FIXED_SLEEP != 1:
|
||||
logger.debug("Time diffs between updates: %s" % self.time_diffs_between_updates)
|
||||
|
||||
# Only keep the 10 latest time diffs
|
||||
if len(self.time_diffs_between_updates) > 10:
|
||||
self.time_diffs_between_updates = self.time_diffs_between_updates[1:]
|
||||
# Only keep the 10 latest time diffs
|
||||
if len(self.time_diffs_between_updates) > 10:
|
||||
self.time_diffs_between_updates = self.time_diffs_between_updates[1:]
|
||||
|
||||
# If we have less than 3 data points,
|
||||
if len(self.time_diffs_between_updates) > 2:
|
||||
sleep_secs = sum(self.time_diffs_between_updates) / len(self.time_diffs_between_updates)
|
||||
# If we have less than 3 data points,
|
||||
if len(self.time_diffs_between_updates) > 2:
|
||||
sleep_secs = sum(self.time_diffs_between_updates) / len(self.time_diffs_between_updates)
|
||||
|
||||
# At minimum, update every AUTOUPDATE_MAX_SLEEP_SECONDS regardless
|
||||
# of how often we're seeing new data appear
|
||||
if sleep_secs > self.secret.AUTOUPDATE_MAX_SLEEP_SECONDS:
|
||||
sleep_secs = self.secret.AUTOUPDATE_MAX_SLEEP_SECONDS
|
||||
# At minimum, update every AUTOUPDATE_MAX_SLEEP_SECONDS regardless
|
||||
# of how often we're seeing new data appear
|
||||
if sleep_secs > self.secret.AUTOUPDATE_MAX_SLEEP_SECONDS:
|
||||
sleep_secs = self.secret.AUTOUPDATE_MAX_SLEEP_SECONDS
|
||||
|
||||
logger.info('Sleeping for %0.01f sec' % sleep_secs)
|
||||
time.sleep(sleep_secs)
|
||||
# Defensive: with the negative-diff filter above, sleep_secs should never be
|
||||
# negative, but legacy state from before the fix or other unexpected inputs
|
||||
# could still produce one. Clamp to AUTOUPDATE_DEFAULT_SLEEP_SECONDS so we
|
||||
# don't crash with ValueError nor tight-loop the API.
|
||||
if sleep_secs < 0:
|
||||
logger.warning(
|
||||
'Computed negative sleep duration (%0.1fs), falling back to default %ds' % (
|
||||
sleep_secs, self.secret.AUTOUPDATE_DEFAULT_SLEEP_SECONDS
|
||||
)
|
||||
)
|
||||
sleep_secs = self.secret.AUTOUPDATE_DEFAULT_SLEEP_SECONDS
|
||||
|
||||
self.autoupdate_invocations += 1
|
||||
if self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS > 0 and self.autoupdate_invocations >= self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS:
|
||||
return 0
|
||||
logger.info('Sleeping for %0.01f sec' % sleep_secs)
|
||||
time.sleep(sleep_secs)
|
||||
|
||||
self.autoupdate_invocations += 1
|
||||
if self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS > 0 and self.autoupdate_invocations >= self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS:
|
||||
return 0
|
||||
|
||||
except ApiLoginException:
|
||||
# A credentials failure is not transient: retrying it in-process
|
||||
# would hammer the login endpoint with attempts that cannot
|
||||
# succeed, which is the exact ban risk the backoff below exists
|
||||
# to prevent. Stay fatal so the user notices and fixes config.
|
||||
raise
|
||||
|
||||
except (
|
||||
ApiException,
|
||||
requests.exceptions.ConnectionError,
|
||||
requests.exceptions.Timeout,
|
||||
requests.exceptions.ChunkedEncodingError,
|
||||
requests.exceptions.RetryError,
|
||||
) as e:
|
||||
# Two failure families, one response. Transient network errors
|
||||
# (DNS, refused connections, timeouts, mid-stream disconnects,
|
||||
# urllib3 retry-budget exhaustion) and API errors that get()
|
||||
# does not retry itself (it only handles 401 and 500 — a 404,
|
||||
# 502 or 503 propagates) both used to exit the process and let
|
||||
# Docker restart the container.
|
||||
#
|
||||
# Restarting is the worst possible response: the credentials
|
||||
# cache dies with the process, so every restart performs a full
|
||||
# login. During the 2026-07-16 EU outage that meant a fresh
|
||||
# login every ~2 minutes for hours from a single IP. Staying in
|
||||
# the loop keeps the cache warm and the login endpoint untouched.
|
||||
self.consecutive_failures += 1
|
||||
if self.first_failure_time is None:
|
||||
self.first_failure_time = time.time()
|
||||
sleep_secs = self._retry_sleep_seconds()
|
||||
|
||||
log = logger.error if self.consecutive_failures >= RETRY_ESCALATE_AFTER_FAILURES else logger.warning
|
||||
log(
|
||||
'Error during autoupdate poll (%d consecutive): %s. Sleeping %ds before retry.' % (
|
||||
self.consecutive_failures, e, sleep_secs
|
||||
)
|
||||
)
|
||||
|
||||
time.sleep(sleep_secs)
|
||||
|
||||
# Staying alive forever would make a real outage silent on
|
||||
# deployments whose only alarm is the container dying. Once the
|
||||
# API has been unreachable for AUTOUPDATE_API_FAILURE_MINUTES,
|
||||
# exit so the platform can restart us and raise its own alert.
|
||||
failing_for = time.time() - self.first_failure_time
|
||||
if self.secret.AUTOUPDATE_API_FAILURE_MINUTES > 0 and failing_for >= 60 * self.secret.AUTOUPDATE_API_FAILURE_MINUTES:
|
||||
logger.error(
|
||||
AutoupdateFailureError(
|
||||
'%s: API has been failing for %d minutes (%d consecutive attempts). '
|
||||
'Exiting so the container platform restarts and reports it.' % (
|
||||
datetime.datetime.now(), failing_for // 60, self.consecutive_failures
|
||||
)
|
||||
)
|
||||
)
|
||||
return 1
|
||||
|
||||
self.autoupdate_invocations += 1
|
||||
if self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS > 0 and self.autoupdate_invocations >= self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS:
|
||||
return 0
|
||||
|
||||
def _retry_sleep_seconds(self):
|
||||
"""Exponential backoff for consecutive failed polls: 30, 60, 120, 240,
|
||||
then held at AUTOUPDATE_DEFAULT_SLEEP_SECONDS (300s default). The cap
|
||||
reuses the existing poll interval because a failing API should never be
|
||||
contacted more often than a healthy one."""
|
||||
backoff = RETRY_INITIAL_SLEEP_SECONDS * (2 ** (self.consecutive_failures - 1))
|
||||
return min(backoff, self.secret.AUTOUPDATE_DEFAULT_SLEEP_SECONDS)
|
||||
|
||||
|
||||
class AutoupdateError(RuntimeError):
|
||||
|
||||
@@ -0,0 +1,679 @@
|
||||
#!/usr/bin/env python3
|
||||
"""
|
||||
Regression tests for negative-sleep crash in TandemSourceAutoupdate.
|
||||
|
||||
When the pump's reported maxDateWithEvents is interpreted as being in the
|
||||
future (e.g. timezone mismatch where arrow tags a local-time string as UTC),
|
||||
`now - last_max_date_with_events` produced a negative value that landed in
|
||||
the rolling-average list, which in turn fed `time.sleep()` and crashed the
|
||||
process with `ValueError: sleep length must be non-negative`.
|
||||
"""
|
||||
|
||||
import unittest
|
||||
from unittest.mock import patch
|
||||
|
||||
import arrow
|
||||
import requests
|
||||
|
||||
from tconnectsync.api.common import ApiException, ApiLoginException
|
||||
from tconnectsync.sync.tandemsource.autoupdate import TandemSourceAutoupdate
|
||||
|
||||
from ...secrets import build_secrets
|
||||
|
||||
|
||||
class _FakeTConnect:
|
||||
pass
|
||||
|
||||
|
||||
class _FakeNightscout:
|
||||
pass
|
||||
|
||||
|
||||
class TestAutoupdateNegativeSleep(unittest.TestCase):
|
||||
def setUp(self):
|
||||
self.secret = build_secrets(
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=1,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
)
|
||||
|
||||
def _run_one_iteration(self, autoupdate, future_offset_seconds=None, max_date_iso=None):
|
||||
"""Drive one autoupdate loop iteration. Either pass `future_offset_seconds`
|
||||
(produces a UTC-tagged ISO string `future_offset_seconds` ahead of now) or
|
||||
pass `max_date_iso` directly (used by tests that need a specific format,
|
||||
e.g. naive local-time strings to exercise the TIMEZONE_NAME parsing fix)."""
|
||||
if max_date_iso is None:
|
||||
assert future_offset_seconds is not None
|
||||
max_date_iso = arrow.utcnow().shift(seconds=future_offset_seconds).isoformat()
|
||||
future_iso = max_date_iso
|
||||
|
||||
sleep_calls = []
|
||||
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.return_value = {
|
||||
"assignmentId": "test-device-1",
|
||||
"maxDateOfEvents": future_iso,
|
||||
}
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
|
||||
autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
return sleep_calls
|
||||
|
||||
def test_time_sleep_never_called_with_negative_value(self):
|
||||
"""Defensive clamp: even with negative rolling-avg entries, time.sleep
|
||||
must receive a non-negative argument."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
# Simulate state after prior iterations where pump timestamps were
|
||||
# consistently ~2h in the future (TZ skew).
|
||||
autoupdate.time_diffs_between_updates = [-7200.0, -7200.0, -7200.0]
|
||||
autoupdate.last_max_date_with_events = (
|
||||
arrow.utcnow().float_timestamp + 7200
|
||||
)
|
||||
autoupdate.last_event_seqnum = 12345
|
||||
|
||||
sleep_calls = self._run_one_iteration(autoupdate, future_offset_seconds=7260)
|
||||
|
||||
self.assertTrue(sleep_calls, "Expected at least one time.sleep call")
|
||||
for call_arg in sleep_calls:
|
||||
self.assertGreaterEqual(
|
||||
call_arg, 0,
|
||||
"time.sleep was called with negative value %r" % call_arg,
|
||||
)
|
||||
|
||||
def test_negative_diff_not_recorded_in_rolling_average(self):
|
||||
"""Root cause: a negative `now - last_max_date_with_events` indicates
|
||||
clock skew and must not be appended to the rolling-average list."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
# Previous max-date is 2h in the future, so `now - past_future = negative`.
|
||||
autoupdate.last_max_date_with_events = (
|
||||
arrow.utcnow().float_timestamp + 7200
|
||||
)
|
||||
autoupdate.last_event_seqnum = 12345
|
||||
|
||||
self._run_one_iteration(autoupdate, future_offset_seconds=7260)
|
||||
|
||||
for diff in autoupdate.time_diffs_between_updates:
|
||||
self.assertGreaterEqual(
|
||||
diff, 0,
|
||||
"Negative diff %r leaked into time_diffs_between_updates" % diff,
|
||||
)
|
||||
|
||||
def test_positive_diff_is_still_recorded(self):
|
||||
"""Sanity check: the happy path (pump timestamp in the past) still
|
||||
feeds the rolling average."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
# Previous max-date is 5min in the PAST — normal case.
|
||||
autoupdate.last_max_date_with_events = (
|
||||
arrow.utcnow().float_timestamp - 300
|
||||
)
|
||||
autoupdate.last_event_seqnum = 12345
|
||||
|
||||
self._run_one_iteration(autoupdate, future_offset_seconds=60)
|
||||
|
||||
self.assertEqual(
|
||||
len(autoupdate.time_diffs_between_updates), 1,
|
||||
"Expected exactly one positive diff to be recorded",
|
||||
)
|
||||
self.assertGreater(autoupdate.time_diffs_between_updates[0], 0)
|
||||
|
||||
|
||||
class TestAutoupdateNaiveTimestampParsing(unittest.TestCase):
|
||||
"""Root cause regression: Tandem Source EU returns maxDateOfEvents as a
|
||||
naive ISO string in the pump's local timezone (no offset marker). Before
|
||||
the fix, arrow.get() defaulted naive strings to UTC, shifting the timestamp
|
||||
into the future of `now` by the local UTC offset and producing chronic
|
||||
negative time diffs (every cycle in production logs from 2026-05-19/20).
|
||||
|
||||
Parsing now routes through the API layer's naive_local_to_utc(), which
|
||||
applies tzinfo=TIMEZONE_NAME only when the string carries no offset marker.
|
||||
Strings with an embedded offset (Z, +HH, +HHMM, +HH:MM) are honored as-is.
|
||||
|
||||
Note that naive_local_to_utc() reads the module-level TIMEZONE_NAME rather
|
||||
than the secret object passed to TandemSourceAutoupdate, so these tests
|
||||
patch the constant where the function looks it up. Both resolve to the same
|
||||
env var in production."""
|
||||
|
||||
def test_naive_local_time_string_parsed_in_configured_tz(self):
|
||||
secret = build_secrets(
|
||||
TIMEZONE_NAME="Europe/Berlin",
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=1,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
)
|
||||
autoupdate = TandemSourceAutoupdate(secret)
|
||||
|
||||
# Simulate the production scenario: pump reports its local wall-clock
|
||||
# time as a naive ISO string with no offset marker.
|
||||
now_berlin = arrow.now("Europe/Berlin")
|
||||
naive_local_iso = now_berlin.format("YYYY-MM-DDTHH:mm:ss")
|
||||
self.assertNotIn("+", naive_local_iso, "fixture must be naive (no TZ)")
|
||||
self.assertNotIn("Z", naive_local_iso, "fixture must be naive (no TZ)")
|
||||
|
||||
sleep_calls = []
|
||||
with patch(
|
||||
"tconnectsync.api.tandemsource.TIMEZONE_NAME", "Europe/Berlin"
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.return_value = {
|
||||
"assignmentId": "test-device-1",
|
||||
"maxDateOfEvents": naive_local_iso,
|
||||
}
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
|
||||
autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
# After the fix, the parsed epoch should match wall-clock now (give or
|
||||
# take a second for test execution), NOT now + UTC_offset.
|
||||
recorded_epoch = autoupdate.last_max_date_with_events
|
||||
wall_clock_epoch = arrow.utcnow().float_timestamp
|
||||
delta = abs(recorded_epoch - wall_clock_epoch)
|
||||
self.assertLess(
|
||||
delta, 10,
|
||||
"Naive local-time string was misinterpreted as UTC (delta=%0.1fs). "
|
||||
"Expected parser to honor TIMEZONE_NAME=Europe/Berlin." % delta,
|
||||
)
|
||||
|
||||
def test_embedded_tz_marker_still_honored(self):
|
||||
"""A maxDateWithEvents that DOES carry an offset (e.g. US fixtures,
|
||||
future format changes) must still parse correctly even with a
|
||||
mismatching TIMEZONE_NAME, because the helper short-circuits to
|
||||
plain arrow.get() when an offset is present."""
|
||||
secret = build_secrets(
|
||||
TIMEZONE_NAME="Europe/Berlin", # deliberately wrong for the fixture
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=1,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
)
|
||||
autoupdate = TandemSourceAutoupdate(secret)
|
||||
|
||||
# Pump in US Eastern reports with explicit -05:00 / -04:00 offset,
|
||||
# like the existing test_process.py fixture.
|
||||
now_eastern = arrow.now("America/New_York")
|
||||
tz_tagged_iso = now_eastern.isoformat()
|
||||
self.assertIn(
|
||||
":", tz_tagged_iso[-6:],
|
||||
"fixture must include an explicit TZ offset",
|
||||
)
|
||||
|
||||
sleep_calls = []
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.return_value = {
|
||||
"assignmentId": "test-device-1",
|
||||
"maxDateOfEvents": tz_tagged_iso,
|
||||
}
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
|
||||
autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
recorded_epoch = autoupdate.last_max_date_with_events
|
||||
wall_clock_epoch = arrow.utcnow().float_timestamp
|
||||
delta = abs(recorded_epoch - wall_clock_epoch)
|
||||
self.assertLess(
|
||||
delta, 10,
|
||||
"Embedded TZ offset was overridden by TIMEZONE_NAME (delta=%0.1fs). "
|
||||
"Helper should short-circuit to arrow.get() when offset present." % delta,
|
||||
)
|
||||
|
||||
|
||||
class TestAutoupdateTransientNetworkError(unittest.TestCase):
|
||||
"""Regression: DNS failures and connection resets used to propagate up
|
||||
from ChooseDevice / ProcessTimeRange and exit the process, leading
|
||||
Docker/Synology to restart the container hourly and email the user.
|
||||
|
||||
The fix wraps the loop body in a try/except for requests' ConnectionError,
|
||||
Timeout, ChunkedEncodingError, and RetryError; logs a warning; sleeps;
|
||||
and continues. Sustained outages still trigger the NO_DATA_FAILURE_MINUTES
|
||||
safety net (covered by other paths).
|
||||
|
||||
Network errors share the incremental backoff of TestAutoupdateApiErrorBackoff
|
||||
(30s, doubling, capped at DEFAULT_SLEEP_SECONDS) rather than the flat
|
||||
DEFAULT_SLEEP_SECONDS they originally used: a 2-second DNS blip should not
|
||||
cost a 5-minute sync gap, while a real outage still settles at 5 minutes."""
|
||||
|
||||
def setUp(self):
|
||||
self.secret = build_secrets(
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=2,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
)
|
||||
|
||||
def _drive(self, autoupdate, choose_side_effect):
|
||||
"""Drive autoupdate.process() with patched ChooseDevice and ProcessTimeRange.
|
||||
Returns (sleep_calls, result)."""
|
||||
sleep_calls = []
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.side_effect = choose_side_effect
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
result = autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
return sleep_calls, result, future_iso
|
||||
|
||||
def test_connection_error_does_not_crash_loop(self):
|
||||
"""A DNS failure on the first iteration must not exit the process;
|
||||
the loop should sleep and try again."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
sleep_calls, result, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
requests.exceptions.ConnectionError(
|
||||
"HTTPSConnectionPool(host='source.eu.tandemdiabetes.com', port=443): "
|
||||
"Max retries exceeded with url: /api/... "
|
||||
"(Caused by NameResolutionError(...Temporary failure in name resolution))"
|
||||
),
|
||||
{"assignmentId": "test-device-1", "maxDateOfEvents": future_iso},
|
||||
],
|
||||
)
|
||||
|
||||
self.assertIn(result, (0, None))
|
||||
self.assertEqual(autoupdate.autoupdate_invocations, 2)
|
||||
self.assertGreaterEqual(len(sleep_calls), 2)
|
||||
self.assertEqual(
|
||||
sleep_calls[0], 30,
|
||||
"First retry after a network blip should be the short backoff, "
|
||||
"not a flat 5-minute wait",
|
||||
)
|
||||
|
||||
def test_timeout_does_not_crash_loop(self):
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
sleep_calls, _, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
requests.exceptions.Timeout("Read timed out"),
|
||||
{"assignmentId": "x", "maxDateOfEvents": future_iso},
|
||||
],
|
||||
)
|
||||
self.assertEqual(autoupdate.autoupdate_invocations, 2)
|
||||
self.assertGreaterEqual(len(sleep_calls), 2)
|
||||
|
||||
def test_chunked_encoding_error_does_not_crash_loop(self):
|
||||
"""A mid-stream disconnect during pump_events download surfaces as
|
||||
ChunkedEncodingError (subclass of RequestException, NOT ConnectionError),
|
||||
so it must be in the catch tuple explicitly."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
_, _, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
requests.exceptions.ChunkedEncodingError("Connection broken"),
|
||||
{"assignmentId": "x", "maxDateOfEvents": future_iso},
|
||||
],
|
||||
)
|
||||
self.assertEqual(autoupdate.autoupdate_invocations, 2)
|
||||
|
||||
def test_retry_error_does_not_crash_loop(self):
|
||||
"""urllib3 retry-budget exhaustion bubbles up as requests.RetryError,
|
||||
which is RequestException but not ConnectionError."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
_, _, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
requests.exceptions.RetryError("Max retries exceeded"),
|
||||
{"assignmentId": "x", "maxDateOfEvents": future_iso},
|
||||
],
|
||||
)
|
||||
self.assertEqual(autoupdate.autoupdate_invocations, 2)
|
||||
|
||||
def test_non_network_exception_still_propagates(self):
|
||||
"""Programming bugs (e.g. KeyError) must NOT be swallowed by the
|
||||
network-error handler — they should still crash so they get noticed."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
):
|
||||
mock_choose.return_value.choose.side_effect = KeyError("simulated bug")
|
||||
with self.assertRaises(KeyError):
|
||||
autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
def test_max_loop_invocations_respected_on_persistent_failure(self):
|
||||
"""If the network never recovers, the loop must still terminate at
|
||||
MAX_LOOP_INVOCATIONS rather than spinning forever."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
sleep_calls = []
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
):
|
||||
mock_choose.return_value.choose.side_effect = (
|
||||
requests.exceptions.ConnectionError("dns fail")
|
||||
)
|
||||
result = autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
self.assertIn(result, (0, None))
|
||||
self.assertEqual(
|
||||
autoupdate.autoupdate_invocations,
|
||||
self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS,
|
||||
)
|
||||
|
||||
|
||||
class TestAutoupdateApiErrorBackoff(unittest.TestCase):
|
||||
"""Regression: on 2026-07-16 Tandem retired the reportsfacade endpoints in
|
||||
the EU region, so pump_event_metadata() began returning HTTP 404. get()
|
||||
only retries 401 and 500, so the ApiException propagated out of the loop
|
||||
and exited the process. Docker restarted the container roughly every two
|
||||
minutes, and because the credentials cache is lost on restart, EVERY
|
||||
restart performed a fresh login against sso.tandemdiabetes.com — hundreds
|
||||
of logins per hour from one IP, which risks a WAF ban.
|
||||
|
||||
The fix keeps API errors inside the loop and backs off incrementally
|
||||
(30s, 60s, 120s, ... capped at AUTOUPDATE_DEFAULT_SLEEP_SECONDS) so the
|
||||
process stays alive, the credentials cache stays warm, and a sustained
|
||||
outage settles into one quiet poll every 5 minutes."""
|
||||
|
||||
def setUp(self):
|
||||
self.secret = build_secrets(
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=6,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
)
|
||||
|
||||
def _drive(self, autoupdate, choose_side_effect):
|
||||
sleep_calls = []
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=lambda s: sleep_calls.append(s),
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.side_effect = choose_side_effect
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
result = autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
return sleep_calls, result
|
||||
|
||||
def test_api_exception_does_not_crash_loop(self):
|
||||
"""The production symptom: HTTP 404 from pumpeventmetadata must be
|
||||
survivable, not fatal."""
|
||||
# One failure + one success, so stop the loop after two invocations
|
||||
# rather than running past the fixtures.
|
||||
self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS = 2
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
|
||||
sleep_calls, result = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
ApiException(404, "TandemSourceApi HTTP 404 response: "),
|
||||
{"assignmentId": "test-device-1", "maxDateOfEvents": future_iso},
|
||||
],
|
||||
)
|
||||
|
||||
self.assertIn(result, (0, None))
|
||||
self.assertGreaterEqual(len(sleep_calls), 2)
|
||||
|
||||
def test_backoff_grows_incrementally_and_caps_at_default_sleep(self):
|
||||
"""A persistent outage must not poll at a fixed fast rate. Waits grow
|
||||
30 -> 60 -> 120 -> 240 and then hold at AUTOUPDATE_DEFAULT_SLEEP_SECONDS
|
||||
(300s = 5 minutes), never above it."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
|
||||
sleep_calls, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=ApiException(404, "TandemSourceApi HTTP 404 response: "),
|
||||
)
|
||||
|
||||
self.assertEqual(sleep_calls, [30, 60, 120, 240, 300, 300])
|
||||
|
||||
def test_backoff_resets_after_successful_iteration(self):
|
||||
"""A single blip must not permanently penalize the poll rate: once a
|
||||
poll succeeds, the next failure starts again at the shortest wait."""
|
||||
# Four fixtures below, so stop after four invocations.
|
||||
self.secret.AUTOUPDATE_MAX_LOOP_INVOCATIONS = 4
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
device = {"assignmentId": "test-device-1", "maxDateOfEvents": future_iso}
|
||||
|
||||
sleep_calls, _ = self._drive(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
ApiException(502, "TandemSourceApi HTTP 502 response: "),
|
||||
ApiException(502, "TandemSourceApi HTTP 502 response: "),
|
||||
device,
|
||||
ApiException(502, "TandemSourceApi HTTP 502 response: "),
|
||||
],
|
||||
)
|
||||
|
||||
# Expected: 30 and 60 for the two failures, then the normal poll
|
||||
# interval for the successful iteration, then back to 30 — not 120 —
|
||||
# because the success reset the counter.
|
||||
self.assertEqual(
|
||||
sleep_calls[:2], [30, 60],
|
||||
"Expected the first outage to back off 30 then 60, got %r" % sleep_calls,
|
||||
)
|
||||
self.assertEqual(
|
||||
sleep_calls[-1], 30,
|
||||
"Backoff must reset to 30s after the successful poll in between, "
|
||||
"got %r (full sequence: %r)" % (sleep_calls[-1], sleep_calls),
|
||||
)
|
||||
|
||||
def test_login_exception_still_propagates(self):
|
||||
"""Guard: a credentials failure is NOT transient. Retrying it in-process
|
||||
would hammer the login endpoint with doomed attempts, which is exactly
|
||||
the ban risk this backoff exists to avoid. It must stay fatal so the
|
||||
user notices and fixes their config."""
|
||||
autoupdate = TandemSourceAutoupdate(self.secret)
|
||||
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
):
|
||||
mock_choose.return_value.choose.side_effect = ApiLoginException(
|
||||
401, "Invalid credentials"
|
||||
)
|
||||
with self.assertRaises(ApiLoginException):
|
||||
autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
|
||||
class TestAutoupdateSustainedFailureExit(unittest.TestCase):
|
||||
"""Staying alive through an outage costs the only alarm this deployment
|
||||
has: Synology's Container Manager mails on container exit, and nothing
|
||||
watches the log stream. With the backoff swallowing API errors forever, a
|
||||
real outage (like the 2026-07-16 EU cutover) would now be silent.
|
||||
|
||||
So a sustained failure escalates one final step: after
|
||||
AUTOUPDATE_API_FAILURE_MINUTES of unbroken failure, exit non-zero. Docker
|
||||
restarts, Synology sends exactly one mail per outage-hour instead of one
|
||||
per two minutes. Short blips stay silent, which is the whole point.
|
||||
|
||||
This is deliberately NOT gated on AUTOUPDATE_RESTART_ON_FAILURE: that flag
|
||||
covers the pump-not-uploading watchdog, where restarting fixes nothing.
|
||||
A dead API is a different failure and deserves its own knob."""
|
||||
|
||||
def _secret(self, **overrides):
|
||||
base = dict(
|
||||
AUTOUPDATE_DEFAULT_SLEEP_SECONDS=300,
|
||||
AUTOUPDATE_MAX_SLEEP_SECONDS=1500,
|
||||
AUTOUPDATE_UNEXPECTED_NO_INDEX_SLEEP_SECONDS=60,
|
||||
AUTOUPDATE_USE_FIXED_SLEEP=0,
|
||||
AUTOUPDATE_MAX_LOOP_INVOCATIONS=50,
|
||||
AUTOUPDATE_NO_DATA_FAILURE_MINUTES=180,
|
||||
AUTOUPDATE_FAILURE_MINUTES=75,
|
||||
AUTOUPDATE_RESTART_ON_FAILURE=False,
|
||||
AUTOUPDATE_API_FAILURE_MINUTES=45,
|
||||
)
|
||||
base.update(overrides)
|
||||
return build_secrets(**base)
|
||||
|
||||
def _drive_with_clock(self, autoupdate, choose_side_effect):
|
||||
"""Drive the loop with a fake clock that advances by each sleep, so
|
||||
simulated wall-clock time passes without the test actually waiting."""
|
||||
clock = [10_000.0]
|
||||
sleeps = []
|
||||
|
||||
def fake_sleep(secs):
|
||||
sleeps.append(secs)
|
||||
clock[0] += secs
|
||||
|
||||
with patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.sleep",
|
||||
side_effect=fake_sleep,
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.time.time",
|
||||
side_effect=lambda: clock[0],
|
||||
), patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ChooseDevice"
|
||||
) as mock_choose, patch(
|
||||
"tconnectsync.sync.tandemsource.autoupdate.ProcessTimeRange"
|
||||
) as mock_process:
|
||||
mock_choose.return_value.choose.side_effect = choose_side_effect
|
||||
mock_process.return_value.process.return_value = (1, 999)
|
||||
result = autoupdate.process(_FakeTConnect(), _FakeNightscout(), pretend=False)
|
||||
|
||||
return result, sleeps, clock[0] - 10_000.0
|
||||
|
||||
def test_exits_nonzero_after_sustained_api_failure(self):
|
||||
"""The production scenario: a dead endpoint. After 45 simulated minutes
|
||||
of unbroken 404s the process must exit non-zero so the platform mails."""
|
||||
autoupdate = TandemSourceAutoupdate(self._secret())
|
||||
|
||||
result, sleeps, elapsed = self._drive_with_clock(
|
||||
autoupdate,
|
||||
choose_side_effect=ApiException(404, "TandemSourceApi HTTP 404 response: "),
|
||||
)
|
||||
|
||||
self.assertEqual(result, 1, "Expected a non-zero exit after a sustained outage")
|
||||
self.assertGreaterEqual(
|
||||
elapsed, 45 * 60,
|
||||
"Exited after only %0.0fs; must persist a full AUTOUPDATE_API_FAILURE_MINUTES "
|
||||
"before giving up" % elapsed,
|
||||
)
|
||||
self.assertLess(
|
||||
elapsed, 75 * 60,
|
||||
"Took %0.0fs to give up; backoff should reach the threshold promptly "
|
||||
"once capped" % elapsed,
|
||||
)
|
||||
|
||||
def test_recovery_before_threshold_does_not_exit(self):
|
||||
"""A 10-minute outage that recovers must not trigger a mail."""
|
||||
autoupdate = TandemSourceAutoupdate(self._secret(AUTOUPDATE_MAX_LOOP_INVOCATIONS=6))
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
device = {"assignmentId": "x", "maxDateOfEvents": future_iso}
|
||||
|
||||
result, _, _ = self._drive_with_clock(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
ApiException(503, "down"),
|
||||
ApiException(503, "down"),
|
||||
ApiException(503, "down"),
|
||||
device,
|
||||
device,
|
||||
device,
|
||||
],
|
||||
)
|
||||
|
||||
self.assertIn(result, (0, None), "A recovered outage must not exit non-zero")
|
||||
|
||||
def test_failure_clock_resets_on_success(self):
|
||||
"""Two separate short outages must not add up to an exit: the failure
|
||||
clock restarts from the successful poll between them."""
|
||||
autoupdate = TandemSourceAutoupdate(self._secret(AUTOUPDATE_MAX_LOOP_INVOCATIONS=12))
|
||||
future_iso = arrow.utcnow().shift(seconds=60).isoformat()
|
||||
device = {"assignmentId": "x", "maxDateOfEvents": future_iso}
|
||||
|
||||
result, _, _ = self._drive_with_clock(
|
||||
autoupdate,
|
||||
choose_side_effect=[
|
||||
ApiException(503, "down"), ApiException(503, "down"),
|
||||
ApiException(503, "down"), ApiException(503, "down"),
|
||||
ApiException(503, "down"),
|
||||
device,
|
||||
ApiException(503, "down"), ApiException(503, "down"),
|
||||
ApiException(503, "down"), ApiException(503, "down"),
|
||||
ApiException(503, "down"), device,
|
||||
],
|
||||
)
|
||||
|
||||
self.assertIn(
|
||||
result, (0, None),
|
||||
"Two short outages separated by a success must not accumulate into an exit",
|
||||
)
|
||||
|
||||
def test_zero_minutes_disables_the_exit(self):
|
||||
"""Opt-out: 0 means never give up, for users who would rather have a
|
||||
silent process than a restarting one."""
|
||||
autoupdate = TandemSourceAutoupdate(
|
||||
self._secret(AUTOUPDATE_API_FAILURE_MINUTES=0, AUTOUPDATE_MAX_LOOP_INVOCATIONS=30)
|
||||
)
|
||||
|
||||
result, _, elapsed = self._drive_with_clock(
|
||||
autoupdate,
|
||||
choose_side_effect=ApiException(404, "gone"),
|
||||
)
|
||||
|
||||
self.assertIn(result, (0, None), "0 must disable the sustained-failure exit")
|
||||
self.assertGreater(
|
||||
elapsed, 45 * 60,
|
||||
"Test must simulate past the default threshold to prove it is ignored",
|
||||
)
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
unittest.main()
|
||||
Reference in New Issue
Block a user