autoupdate: add new config options if no data received, log pretty timestamps

main.py

@@ -4,6 +4,7 @@ import sys
 import datetime
 import arrow
 import argparse
+import logging
 
 from tconnectsync.api import TConnectApi
 from tconnectsync.process import process_time_range
@@ -26,6 +27,7 @@ except Exception:
 def parse_args():
     parser = argparse.ArgumentParser(description="Syncs bolus, basal, and IOB data from Tandem Diabetes t:connect to Nightscout.")
     parser.add_argument('--pretend', dest='pretend', action='store_const', const=True, default=False, help='Pretend mode: do not upload any data to Nightscout.')
+    parser.add_argument('-v', '--verbose', dest='verbose', action='store_const', const=True, default=False, help='Verbose mode: show extra logging details')
     parser.add_argument('--start-date', dest='start_date', type=str, default=None, help='The oldest date to process data from. Must be specified with --end-date.')
     parser.add_argument('--end-date', dest='end_date', type=str, default=None, help='The newest date to process data until (inclusive). Must be specified with --start-date.')
     parser.add_argument('--days', dest='days', type=int, default=1, help='The number of days of t:connect data to read in. Cannot be used with --from-date and --until-date.')
@@ -37,6 +39,12 @@ def parse_args():
 def main():
     args = parse_args()
 
+    if args.verbose:
+        logging.basicConfig(level=logging.DEBUG)
+        logging.root.debug("Set logging level to DEBUG")
+    else:
+        logging.basicConfig(level=logging.INFO)
+
     if args.auto_update and (args.start_date or args.end_date):
         raise Exception('Auto-update cannot be used with start/end date')
 

tconnectsync/api/android.py

@@ -6,11 +6,15 @@ import csv
 import base64
 import arrow
 import time
+import logging
 
 from bs4 import BeautifulSoup
 
+from ..util import timeago
 from .common import ApiException, ApiLoginException
 
+logger = logging.getLogger(__name__)
+
 """
 The AndroidApi class contains methods which are queried in the t:connect
 Android application. These methods are a part of the tdc API which require
@@ -67,6 +71,8 @@ class AndroidApi:
         self.userId = j["user"]["id"]
         self.patientObjectId = j["user"]["patientObjectId"]
 
+        logger.info("Logged in to AndroidApi successfully (expiration: %s, %s)" % (self.accessTokenExpiresAt, timeago(self.accessTokenExpiresAt)))
+
     def needs_relogin(self):
         diff = (arrow.get(self.accessTokenExpiresAt) - arrow.get())
         return (diff.seconds <= 5 * 60)

tconnectsync/api/controliq.py

@@ -7,6 +7,7 @@ import logging
 
 from bs4 import BeautifulSoup
 
+from ..util import timeago
 from .common import parse_date, base_headers, ApiException, ApiLoginException
 
 logger = logging.getLogger(__name__)
@@ -43,6 +44,7 @@ class ControlIQApi:
             self.userGuid = req.cookies['UserGUID']
             self.accessToken = req.cookies['accessToken']
             self.accessTokenExpiresAt = req.cookies['accessTokenExpiresAt']
+            logger.info("Logged in to ControlIQApi successfully (expiration: %s, %s)" % (self.accessTokenExpiresAt, timeago(self.accessTokenExpiresAt)))
             return True
 
     def _build_login_data(self, email, password, soup):

tconnectsync/api/ws2.py

@@ -2,6 +2,7 @@ import requests
 import datetime
 import csv
 import logging
+import time
 
 from .common import parse_date, base_headers, ApiException
 
@@ -66,9 +67,12 @@ class WS2Api:
         try:
             req_text = self.get('therapytimeline2csv/%s/%s/%s?format=csv' % (self.userGuid, startDate, endDate), {})
         except ApiException as e:
+            # This seems to occur as some kind of soft rate-limit.
             logger.warn("Received ApiException in therapy_timeline_csv: (retry count %d) %s" % (tries, e))
             if e.status_code == 500:
-                logger.error("HTTP 500 in therapy_timeline_csv (retry count %d): %s" % (tries, e))
+                sleep_seconds = (tries+1) * 60
+                logger.error("Retrying in %d seconds after HTTP 500 in therapy_timeline_csv (retry count %d): %s" % (sleep_seconds, tries, e))
+                time.sleep(sleep_seconds)
                 if tries < self.MAX_RETRIES:
                     return self.therapy_timeline_csv(start, end, tries+1)
             raise e

tconnectsync/autoupdate.py

@@ -6,7 +6,9 @@ from .secret import (
     PUMP_SERIAL_NUMBER,
     AUTOUPDATE_DEFAULT_SLEEP_SECONDS,
     AUTOUPDATE_MAX_SLEEP_SECONDS,
-    AUTOUPDATE_USE_FIXED_SLEEP
+    AUTOUPDATE_USE_FIXED_SLEEP,
+    AUTOUPDATE_FAILURE_MINUTES,
+    AUTOUPDATE_RESTART_ON_FAILURE
 )
 
 logger = logging.getLogger(__name__)
@@ -34,9 +36,13 @@ def process_auto_update(tconnect, nightscout, time_start, time_end, pretend):
             else:
                 added = process_time_range(tconnect, nightscout, time_start, time_end, pretend)
                 logger.info('Added %d items from process_time_range' % added)
-                if len(added) == 0 and last_event_index:
-                    logger.error('An event index change was recorded, but no new data was found via the API.')
-                    logger.error('If this error reoccurs, try restarting tconnectsync.')
+                if len(added) == 0:
+                    if last_event_index:
+                        logger.error('An event index change was recorded, but no new data was found via the API. ' +
+                                     'If this error reoccurs, try restarting tconnectsync.')
+                else:
+                    last_process_time_range = now
+
 
             if last_event_index:
                 time_diffs.append(now - last_event_time)
@@ -46,6 +52,21 @@ def process_auto_update(tconnect, nightscout, time_start, time_end, pretend):
             last_event_time = now
         else:
             logger.info('No new reported t:connect data. (last event index: %d)' % last_event['maxPumpEventIndex'])
+            now = time.time()
+
+            if (now - last_event_time) >= 60 * AUTOUPDATE_FAILURE_MINUTES:
+                logger.error("No new data event indexes have been detected for over %d minutes. " % AUTOUPDATE_FAILURE_MINUTES +
+                             "The t:connect app might no longer be functioning.")
+
+                if AUTOUPDATE_RESTART_ON_FAILURE:
+                    raise AutoupdateFailureException
+            elif (now - last_process_time_range) >= 60 * AUTOUPDATE_FAILURE_MINUTES:
+                logger.error("No new data has been found via the API for over %d minutes. " % AUTOUPDATE_FAILURE_MINUTES +
+                             "tconnectsync might not be functioning properly.")
+
+                if AUTOUPDATE_RESTART_ON_FAILURE:
+                    raise AutoupdateFailureException
+
 
             if len(time_diffs) > 2:
                 logger.info('Sleeping 60 seconds after unexpected no index change. (New data might be delayed.)')
@@ -65,4 +86,7 @@ def process_auto_update(tconnect, nightscout, time_start, time_end, pretend):
 
         # Sleep for a rolling average of time between updates
         logger.info('Sleeping for %d sec' % sleep_secs)
-        time.sleep(sleep_secs)
+        time.sleep(sleep_secs)
+
+class AutoupdateFailureException(RuntimeError):
+    pass

tconnectsync/process.py

@@ -1,6 +1,9 @@
 import logging
 import datetime
+import arrow
+import time
 
+from .util import timeago
 from .api.common import ApiException
 from .sync.basal import (
     process_ciq_basal_events,
@@ -15,6 +18,7 @@ from .sync.iob import (
     process_iob_events,
     ns_write_iob_events
 )
+from .parser.tconnect import TConnectEntry
 
 logger = logging.getLogger(__name__)
 
@@ -46,7 +50,10 @@ def process_time_range(tconnect, nightscout, time_start, time_end, pretend):
     bolusData = csvdata["bolusData"]
 
     if readingData and len(readingData) > 0:
-        logger.info("Last CGM reading from t:connect: %s" % (readingData[-1]['EventDateTime'] if 'EventDateTime' in readingData[-1] else readingData))
+        lastReading = readingData[-1]['EventDateTime'] if 'EventDateTime' in readingData[-1] else 0
+        lastReading = TConnectEntry._datetime_parse(lastReading)
+        logger.debug(readingData[-1])
+        logger.info("Last CGM reading from t:connect: %s (%s)" % (lastReading, timeago(lastReading)))
     else:
         logger.warn("No last CGM reading is able to be determined")
 

tconnectsync/secret.py

@@ -15,6 +15,9 @@ def get_number(name, default):
         print("Current value: %s" % val)
         sys.exit(1)
 
+def get_bool(name, default):
+    return str(get(name, default) or '').lower() in ('true', '1')
+
 TCONNECT_EMAIL = get('TCONNECT_EMAIL', 'email@email.com')
 TCONNECT_PASSWORD = get('TCONNECT_PASSWORD', 'password')
 
@@ -27,14 +30,17 @@ TIMEZONE_NAME = get('TIMEZONE_NAME', 'America/New_York')
 
 # Optional configuration
 
-AUTOUPDATE_DEFAULT_SLEEP_SECONDS = get_number('AUTOUPDATE_DEFAULT_SLEEP_SECONDS', '60')
-AUTOUPDATE_MAX_SLEEP_SECONDS = get_number('AUTOUPDATE_MAX_SLEEP_SECONDS', '600')
-AUTOUPDATE_USE_FIXED_SLEEP = get_number('AUTOUPDATE_USE_FIXED_SLEEP', '0')
+AUTOUPDATE_DEFAULT_SLEEP_SECONDS = get_number('AUTOUPDATE_DEFAULT_SLEEP_SECONDS', '300') # 5 minutes
+AUTOUPDATE_MAX_SLEEP_SECONDS = get_number('AUTOUPDATE_MAX_SLEEP_SECONDS', '1500') # 25 minutes
+AUTOUPDATE_USE_FIXED_SLEEP = get_bool('AUTOUPDATE_USE_FIXED_SLEEP', 'false')
+AUTOUPDATE_FAILURE_MINUTES = get_number('AUTOUPDATE_FAILURE_MINUTES', '180') # 3 hours
+AUTOUPDATE_RESTART_ON_FAILURE = get_bool('AUTOUPDATE_RESTART_ON_FAILURE', 'false')
 
 _config = ['TCONNECT_EMAIL', 'TCONNECT_PASSWORD', 'PUMP_SERIAL_NUMBER',
           'NS_URL', 'NS_SECRET', 'TIMEZONE_NAME',
           'AUTOUPDATE_DEFAULT_SLEEP_SECONDS', 'AUTOUPDATE_MAX_SLEEP_SECONDS',
-          'AUTOUPDATE_USE_FIXED_SLEEP']
+          'AUTOUPDATE_USE_FIXED_SLEEP', 'AUTOUPDATE_FAILURE_MINUTES',
+          'AUTOUPDATE_RESTART_ON_FAILURE']
 
 if __name__ == '__main__':
     for k in locals():

tconnectsync/sync/basal.py

@@ -62,6 +62,7 @@ def add_csv_basal_events(basalEvents, data):
 Given processed basal data, adds basal events to Nightscout.
 """
 def ns_write_basal_events(nightscout, basalEvents, pretend=False):
+    logger.debug("ns_write_basal_events: querying for last uploaded entry")
     last_upload = nightscout.last_uploaded_entry(BASAL_EVENTTYPE)
     last_upload_time = None
     if last_upload:

tconnectsync/sync/bolus.py

@@ -34,6 +34,7 @@ def process_bolus_events(bolusdata):
 Given processed bolus data, adds bolus events to Nightscout.
 """
 def ns_write_bolus_events(nightscout, bolusEvents, pretend=False):
+    logger.debug("ns_write_bolus_events: querying for last uploaded entry")
     last_upload = nightscout.last_uploaded_entry(BOLUS_EVENTTYPE)
     last_upload_time = None
     if last_upload:

tconnectsync/sync/iob.py

@@ -25,6 +25,7 @@ def process_iob_events(iobdata):
 Given processed IOB data, creates a single Nightscout activity definition to store IOB.
 """
 def ns_write_iob_events(nightscout, iobEvents, pretend=False):
+    logger.debug("ns_write_iob_events: querying for last uploaded entry")
     last_upload = nightscout.last_uploaded_activity(IOB_ACTIVITYTYPE)
     last_upload_time = None
     if last_upload:

tconnectsync/util/__init__.py

@@ -0,0 +1,17 @@
+import arrow
+
+def timeago(timestamp):
+    seconds = (arrow.get() - arrow.get(timestamp)).total_seconds()
+    fmt = '%s ago' if seconds >= 0 else 'in %s'
+    seconds = abs(seconds)
+
+    ret = ''
+    if seconds//86400 > 0:
+        ret += '%d days, ' % (seconds//86400)
+        seconds = seconds % 86400
+    if seconds//3600 > 0:
+        ret += '%d hours, ' % (seconds//3600)
+        seconds = seconds % 3600
+    ret += '%d minutes' % (seconds//60)
+
+    return fmt % ret