logging: use logger instead of prints, improve logging throughout

tconnectsync/api/__init__.py

@@ -1,7 +1,11 @@
+import logging
+
 from .android import AndroidApi
 from .controliq import ControlIQApi
 from .ws2 import WS2Api
 
+logger = logging.getLogger(__name__)
+
 """A wrapper for the three different t:connect API types."""
 class TConnectApi:
     email = None
@@ -21,6 +25,8 @@ class TConnectApi:
         if self._ciq and not self._ciq.needs_relogin():
             return self._ciq
 
+        logger.debug("Instantiating new ControlIQApi")
+
         self._ciq = ControlIQApi(self.email, self.password)
         return self._ciq
 
@@ -29,6 +35,8 @@ class TConnectApi:
         if self._ws2:
             return self._ws2
 
+        logger.debug("Instantiating new WS2Api")
+
         # Trigger login or re-login via controliq api if necessary
         # so userGuid can be accessed from it
         self.controliq
@@ -41,6 +49,8 @@ class TConnectApi:
         if self._android and not self._android.needs_relogin():
             return self._android
 
+        logger.debug("Instantiating new AndroidApi")
+
         self._android = AndroidApi(self.email, self.password)
         return self._android
 

tconnectsync/api/controliq.py

@@ -3,11 +3,14 @@ import urllib
 import datetime
 import arrow
 import time
+import logging
 
 from bs4 import BeautifulSoup
 
 from .common import parse_date, base_headers, ApiException, ApiLoginException
 
+logger = logging.getLogger(__name__)
+
 class ControlIQApi:
     BASE_URL = 'https://tdcservices.tandemdiabetes.com/tconnect/controliq/api/'
     LOGIN_URL = 'https://tconnect.tandemdiabetes.com/login.aspx?ReturnUrl=%2f'
@@ -22,6 +25,7 @@ class ControlIQApi:
         self._password = password
 
     def login(self, email, password):
+        logger.info("Logging in to ControlIQApi...")
         with requests.Session() as s:
             initial = s.get(self.LOGIN_URL, headers=base_headers())
             soup = BeautifulSoup(initial.content, features='lxml')
@@ -76,11 +80,13 @@ class ControlIQApi:
         try:
             return self._get(endpoint, query)
         except ApiException as e:
+            logger.warn("Received ApiException in ControlIQApi with endpoint '%s' (tries %d): %s" % (endpoint, tries, e))
             if tries > 0:
                 raise ApiException(e.status_code, "ControlIQ API HTTP %d on retry #%d: %s", e.status_code, tries, e)
 
             # Trigger automatic re-login, and try again once
             if e.status_code == 401:
+                logger.info("Performing automatic re-login after HTTP 401 for ControlIQApi")
                 self.accessTokenExpiresAt = time.time()
                 self.login(self._email, self._password)
 

tconnectsync/api/ws2.py

@@ -66,6 +66,7 @@ class WS2Api:
         try:
             req_text = self.get('therapytimeline2csv/%s/%s/%s?format=csv' % (self.userGuid, startDate, endDate), {})
         except ApiException as e:
+            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))
                 if tries < self.MAX_RETRIES:

tconnectsync/autoupdate.py

@@ -1,4 +1,5 @@
 import time
+import logging
 
 from .process import process_time_range
 from .secret import (
@@ -8,6 +9,8 @@ from .secret import (
     AUTOUPDATE_USE_FIXED_SLEEP
 )
 
+logger = logging.getLogger(__name__)
+
 """
 Performs the auto-update functionality. Runs indefinitely in a loop
 until stopped (ctrl+c).
@@ -18,30 +21,34 @@ def process_auto_update(tconnect, nightscout, time_start, time_end, pretend):
 
     last_event_index = None
     last_event_time = None
+    last_process_time_range = None
     time_diffs = []
     while True:
         last_event = tconnect.android.last_event_uploaded(PUMP_SERIAL_NUMBER)
         if not last_event_index or last_event['maxPumpEventIndex'] > last_event_index:
             now = time.time()
-            print('New event index:', last_event['maxPumpEventIndex'], 'last:', last_event_index)
+            logger.info('New reported t:connect data. (event index: %d last: %d)' % (last_event['maxPumpEventIndex'], last_event_index))
 
             if pretend:
-                print('Would update now')
+                logger.info('Would update now if not in pretend mode')
             else:
                 added = process_time_range(tconnect, nightscout, time_start, time_end, pretend)
-                print('Added', added, 'items')
+                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 last_event_index:
                 time_diffs.append(now - last_event_time)
-                print('Time diffs:', time_diffs)
+                logger.debug('Updating tracking of time since last update: %s' % time_diffs)
 
             last_event_index = last_event['maxPumpEventIndex']
             last_event_time = now
         else:
-            print('No event index change:', last_event['maxPumpEventIndex'])
+            logger.info('No new reported t:connect data. (last event index: %d)' % last_event['maxPumpEventIndex'])
 
             if len(time_diffs) > 2:
-                print('Sleeping 60 seconds after unexpected no index change')
+                logger.info('Sleeping 60 seconds after unexpected no index change. (New data might be delayed.)')
                 time.sleep(60)
                 continue
 
@@ -57,5 +64,5 @@ def process_auto_update(tconnect, nightscout, time_start, time_end, pretend):
                 sleep_secs = AUTOUPDATE_MAX_SLEEP_SECONDS
 
         # Sleep for a rolling average of time between updates
-        print('Sleeping for', sleep_secs, 'sec')
+        logger.info('Sleeping for %d sec' % sleep_secs)
         time.sleep(sleep_secs)

tconnectsync/process.py

@@ -1,4 +1,5 @@
-from datetime import datetime
+import logging
+import datetime
 
 from .api.common import ApiException
 from .sync.basal import (
@@ -15,13 +16,15 @@ from .sync.iob import (
     ns_write_iob_events
 )
 
+logger = logging.getLogger(__name__)
+
 """
 Given a TConnectApi object and start/end range, performs a single
 cycle of synchronizing data within the time range.
 If pretend is true, then doesn't actually write data to Nightscout.
 """
 def process_time_range(tconnect, nightscout, time_start, time_end, pretend):
-    print("Downloading t:connect ControlIQ data")
+    logger.info("Downloading t:connect ControlIQ data")
     try:
         ciqTherapyTimelineData = tconnect.controliq.therapy_timeline(time_start, time_end)
     except ApiException as e:
@@ -29,12 +32,12 @@ def process_time_range(tconnect, nightscout, time_start, time_end, pretend):
         # device in the time range which is queried. Since it launched in early 2020,
         # ignore 404's before February.
         if e.status_code == 404 and time_start.date() < datetime.date(2020, 2, 1):
-            print("Ignoring HTTP 404 for ControlIQ API request before Feb 2020")
+            logger.warn("Ignoring HTTP 404 for ControlIQ API request before Feb 2020")
             ciqTherapyTimelineData = None
         else:
             raise e
 
-    print("Downloading t:connect CSV data")
+    logger.info("Downloading t:connect CSV data")
     csvdata = tconnect.ws2.therapy_timeline_csv(time_start, time_end)
 
     readingData = csvdata["readingData"]
@@ -43,13 +46,18 @@ def process_time_range(tconnect, nightscout, time_start, time_end, pretend):
     bolusData = csvdata["bolusData"]
 
     if readingData and len(readingData) > 0:
-        print("Last CGM reading from t:connect:", readingData[-1]['EventDateTime'] if 'EventDateTime' in readingData[-1] else readingData)
+        logger.info("Last CGM reading from t:connect: %s" % (readingData[-1]['EventDateTime'] if 'EventDateTime' in readingData[-1] else readingData))
+    else:
+        logger.warn("No last CGM reading is able to be determined")
 
     added = 0
 
     basalEvents = process_ciq_basal_events(ciqTherapyTimelineData)
     if csvBasalData:
+        logger.debug("CSV basal data found: processing it")
         add_csv_basal_events(basalEvents, csvBasalData)
+    else:
+        logger.debug("No CSV basal data found")
 
     added += ns_write_basal_events(nightscout, basalEvents, pretend=pretend)
 
@@ -59,4 +67,5 @@ def process_time_range(tconnect, nightscout, time_start, time_end, pretend):
     iobEvents = process_iob_events(iobData)
     added += ns_write_iob_events(nightscout, iobEvents, pretend=pretend)
 
+    logger.info("Wrote %d events to Nightscout this process cycle")
     return added

tconnectsync/sync/basal.py

@@ -1,4 +1,5 @@
 import arrow
+import logging
 
 from ..parser.nightscout import (
     BASAL_EVENTTYPE,
@@ -6,6 +7,7 @@ from ..parser.nightscout import (
 )
 from ..parser.tconnect import TConnectEntry
 
+logger = logging.getLogger(__name__)
 
 """
 Merges together input from the therapy timeline API
@@ -64,13 +66,13 @@ def ns_write_basal_events(nightscout, basalEvents, pretend=False):
     last_upload_time = None
     if last_upload:
         last_upload_time = arrow.get(last_upload["created_at"])
-    print("Last Nightscout basal upload:", last_upload_time)
+    logger.info("Last Nightscout basal upload: %s" % last_upload_time)
 
     add_count = 0
     for event in basalEvents:
         if last_upload_time and arrow.get(event["time"]) < last_upload_time:
             if pretend:
-                print("Skipping basal event before last upload time:", event)
+                logger.info("Skipping basal event before last upload time: %s" % event)
             continue
 
         recent_needs_update = False
@@ -97,13 +99,14 @@ def ns_write_basal_events(nightscout, basalEvents, pretend=False):
 
         add_count += 1
 
-        print("  Processing basal:", event, "entry:", entry)
+        logger.info("  Processing basal: %s entry: %s" % (event, entry))
         if recent_needs_update:
-            print("Replacing last uploaded entry:", last_upload)
+            logger.info("Replacing last uploaded entry: %s" % last_upload)
             if not pretend:
                 entry['_id'] = last_upload['_id']
                 nightscout.put_entry(entry, entity='treatments')
         elif not pretend:
             nightscout.upload_entry(entry)
 
+    logger.debug("ns_write_basal_events: added %d events" % add_count)
     return add_count

tconnectsync/sync/bolus.py

@@ -1,4 +1,5 @@
 import arrow
+import logging
 
 from ..parser.nightscout import (
     BOLUS_EVENTTYPE,
@@ -6,6 +7,8 @@ from ..parser.nightscout import (
 )
 from ..parser.tconnect import TConnectEntry
 
+logger = logging.getLogger(__name__)
+
 """
 Given bolus data input from the therapy timeline CSV, converts it into a digestable format.
 """
@@ -19,7 +22,7 @@ def process_bolus_events(bolusdata):
                 # Count non-completed bolus if any insulin was delivered (vs. the amount of insulin requested)
                 parsed["description"] += " (%s)" % parsed["completion"]
             else:
-                print("Skipping non-completed bolus data:", b, "parsed:", parsed)
+                logger.warn("Skipping non-completed bolus data (was a bolus in progress?): %s parsed: %s" % (b, parsed))
                 continue
         bolusEvents.append(parsed)
 
@@ -35,13 +38,13 @@ def ns_write_bolus_events(nightscout, bolusEvents, pretend=False):
     last_upload_time = None
     if last_upload:
         last_upload_time = arrow.get(last_upload["created_at"])
-    print("Last Nightscout bolus upload:", last_upload_time)
+    logger.info("Last Nightscout bolus upload: %s" % last_upload_time)
 
     add_count = 0
     for event in bolusEvents:
         if last_upload_time and arrow.get(event["completion_time"]) <= last_upload_time:
             if pretend:
-                print("Skipping basal event before last upload time:", event)
+                logger.info("Skipping basal event before last upload time: %s" % event)
             continue
 
         entry = NightscoutEntry.bolus(
@@ -53,7 +56,7 @@ def ns_write_bolus_events(nightscout, bolusEvents, pretend=False):
 
         add_count += 1
 
-        print("  Processing bolus:", event, "entry:", entry)
+        logger.info("  Processing bolus: %s entry: %s" % (event, entry))
         if not pretend:
             nightscout.upload_entry(entry)
 

tconnectsync/sync/iob.py

@@ -1,4 +1,5 @@
 import arrow
+import logging
 
 from ..parser.nightscout import (
     IOB_ACTIVITYTYPE,
@@ -6,6 +7,8 @@ from ..parser.nightscout import (
 )
 from ..parser.tconnect import TConnectEntry
 
+logger = logging.getLogger(__name__)
+
 """
 Given IOB data input from the therapy timeline CSV, converts it into a digestable format.
 """
@@ -26,15 +29,15 @@ def ns_write_iob_events(nightscout, iobEvents, pretend=False):
     last_upload_time = None
     if last_upload:
         last_upload_time = arrow.get(last_upload["created_at"])
-    print("Last Nightscout iob upload:", last_upload_time)
+    logger.info("Last Nightscout iob upload: %s" % last_upload_time)
 
     if not iobEvents or len(iobEvents) == 0:
-        print("No IOB events: skipping")
+        logger.info("No IOB events present from API: skipping")
         return 0
 
     event = iobEvents[-1]
     if last_upload_time and arrow.get(event["time"]) <= last_upload_time:
-        print("  Skipping already uploaded iob event:", event)
+        logger.info("  Skipping already uploaded iob event: %s" % event)
         return 0
 
     entry = NightscoutEntry.iob(
@@ -42,13 +45,13 @@ def ns_write_iob_events(nightscout, iobEvents, pretend=False):
         created_at=event["time"]
     )
 
-    print("  Processing iob:", event, "entry:", entry)
+    logger.info("  Processing iob: %s entry: %s" % (event, entry))
     if not pretend:
         nightscout.upload_entry(entry, entity='activity')
 
     # Delete the previous activity
     if last_upload and '_id' in last_upload:
-        print("  Deleting old iob entry:", last_upload)
+        logger.info("  Deleting old iob entry: %s" % last_upload)
         if not pretend:
             nightscout.delete_entry('activity/{}'.format(last_upload['_id']))