Routine logging and test thereof

2 files changed, 59 insertions, 7 deletions

diff --git a/jimbrella/routine.py b/jimbrella/routine.py
index 692807e..6a88d41 100644
--- a/jimbrella/routine.py
+++ b/jimbrella/routine.py
@@ -1,3 +1,4 @@
+import logging
 from .database import Database
 from .jform import JForm
 from .config import *
@@ -39,8 +40,22 @@ def chronological_merge(*sheet_lists) -> list:
 def sync_database(takeaway: JForm, giveback: JForm, db: Database):
     takeaway_unread = takeaway.get_unread()
     giveback_unread = giveback.get_unread()
+    logging.info(
+        "Sync database: found %d unread takeaway sheet(s) and %d unread giveback sheet(s)",
+        len(takeaway_unread),
+        len(giveback_unread),
+    )
     unread = chronological_merge(takeaway_unread, giveback_unread)
+    # NOTE: beyond this point `takeaway_unread` and `giveback_unread` are empty
+    #       because chronological_merge popped all their elements
     for sheet in unread:
+        log_args = (
+            sheet["name"],
+            sheet["id"],
+            sheet["phone"],
+            sheet["key"],
+            sheet["date"].isoformat(timespec="seconds"),
+        )
         if sheet["jform_name"] == "takeaway":
             try:
                 db.take_away(
@@ -50,23 +65,49 @@ def sync_database(takeaway: JForm, giveback: JForm, db: Database):
                     sheet["id"],
                     sheet["phone"],
                 )
+                logging.info(
+                    "%s (ID: %s, phone: %s) borrowed umbrella #%d at %s", *log_args
+                )
             except UmbrellaStatusError:
-                pass
+                logging.warning(
+                    "%s (ID: %s, phone: %s) attempted to borrow inavailable umbrella #%d at %s",
+                    *log_args
+                )
             except UmbrellaNotFoundError:
-                pass
+                logging.warning(
+                    "%s (ID: %s, phone: %s) attempted to borrow non-existent umbrella #%d at %s",
+                    *log_args
+                )
         elif sheet["jform_name"] == "giveback":
             try:
-                db.give_back(sheet["key"], sheet["date"])
+                db.give_back(sheet["key"])
+                logging.info(
+                    "%s (ID: %s, phone: %s) returned umbrella #%d at %s", *log_args
+                )
             except UmbrellaStatusError:
-                pass
+                logging.warning(
+                    "%s (ID: %s, phone: %s) attempted to return available umbrella #%d at %s",
+                    *log_args
+                )
             except UmbrellaNotFoundError:
-                pass
+                logging.warning(
+                    "%s (ID: %s, phone: %s) attempted to return non-existent umbrella #%d at %s",
+                    *log_args
+                )
 
 
 def process_overdue(db: Database):
     overdue = Database.find_overdue(db.read())
-    for umb in overdue:
-        db.mark_overdue(umb["serial"], local_now())
+    # mark and log umbrellas that were not, but just became overdue
+    for umb in filter(lambda u: u["status"] == "lent", overdue):
+        db.mark_overdue(umb["serial"])
+        logging.warning(
+            "Umbrella #%d is now overdue, tenant: %s (ID: %s, phone: %s)",
+            umb["serial"],
+            umb["tenant_name"],
+            umb["tenant_id"],
+            umb["tenant_phone"],
+        )
 
 
 if __name__ == "__main__":
diff --git a/jimbrella/test/test_routine.py b/jimbrella/test/test_routine.py
index 5a08fdf..2a65b35 100644
--- a/jimbrella/test/test_routine.py
+++ b/jimbrella/test/test_routine.py
@@ -3,12 +3,22 @@ from threading import Thread
 import json
 import os
 import shutil
+import logging
 from .jform_data import mock_jform_data
 from ..routine import sync_database, process_overdue
 from ..database import Database
 from ..jform import JForm
 from ..config import *
 
+"""Set up logging."""
+logging.basicConfig(
+    filename="/tmp/jimbrella.log",
+    encoding="utf-8",
+    level=logging.INFO,
+    format="[%(asctime)s] %(levelname)s:%(name)s:%(message)s",
+)
+logging.info("----- BEGIN ROUTINE TEST -----")
+
 """Spin up a simple Flask app to mimic jForm."""
 jform = Flask(__name__)
 
@@ -59,3 +69,4 @@ process_overdue(db)
 """Cleanup"""
 os.remove(takeaway_jform._bookmark_fp)
 os.remove(giveback_jform._bookmark_fp)
+logging.info("----- END ROUTINE TEST -----")