DBC22-4246: Improve huey logging

* DBC22-4246: add huey consumer logging to django configuration

* DBC22-4246: improve huey error handling

* DBC22-4246: rebase logging config

* DBC22-4246: cleanup huey logger

Author: uhelm

.env.example

@@ -21,6 +21,8 @@ DJANGO_EMAIL_HOST=<smtp host>
 DJANGO_EMAIL_PORT=<smtp port>
 DJANGO_FROM_EMAIL_DEFAULT=<default from email for all outgoing emails>
 DJANGO_FEEDBACK_EMAIL_DEFAULT=<default feedback recipient email>
+ROOT_LOG_LEVEL='WARNING'
+HUEY_LOG_LEVEL='INFO'
 
 # Django image database connection details
 DB_NAME=<database name>

src/backend/apps/webcam/tasks.py

@@ -28,6 +28,7 @@
 from django.db.models import F
 from PIL import Image, ImageDraw, ImageFont
 from psycopg import IntegrityError
+from huey.exceptions import CancelExecution
 
 logger = logging.getLogger(__name__)
 
@@ -63,7 +64,7 @@ def populate_all_webcam_data():
         # Check if the task has timed out at the start of each iteration
         if time.time() - start_time > CAMERA_TASK_DEFAULT_TIMEOUT:
             logger.warning(f"populate_all_webcam_data stopped: exceeded {CAMERA_TASK_DEFAULT_TIMEOUT} seconds.")
-            return
+            raise CancelExecution()
 
         populate_webcam_from_data(webcam_data)
 
@@ -95,7 +96,7 @@ def update_all_webcam_data():
         # Check if the task has timed out at the start of each iteration
         if time.time() - start_time > CAMERA_TASK_DEFAULT_TIMEOUT:
             logger.warning(f"update_all_webcam_data stopped: exceeded {CAMERA_TASK_DEFAULT_TIMEOUT} seconds.")
-            return
+            raise CancelExecution()
 
         current_time = datetime.datetime.now(tz=ZoneInfo("America/Vancouver"))
         if camera.should_update(current_time):
@@ -158,6 +159,7 @@ def update_webcam_image(webcam):
             base_url = base_url[:-1]
         endpoint = f'{base_url}/webcams/{webcam["id"]}/imageSource'
 
+        logger.info(f"Requesting GET {endpoint}")
         with urllib.request.urlopen(endpoint, timeout=10) as url:
             image_data = io.BytesIO(url.read())
 
@@ -217,7 +219,7 @@ def update_webcam_image(webcam):
             delta = mean - stddev
 
         except Exception as e:
-            logger.info(e)
+            logger.exception(e)
 
         if lastmod is not None:
             delta = datetime.timedelta(seconds=delta)

src/backend/config/settings/django.py

@@ -197,22 +197,34 @@
 
 # Logging
 ROOT_LOG_LEVEL = env('ROOT_LOG_LEVEL', default='WARNING')
+HUEY_LOG_LEVEL = env('HUEY_LOG_LEVEL', default='INFO')
+
 LOGGING = {
     "version": 1,
     "disable_existing_loggers": False,
     "handlers": {
         "console": {
             "class": "logging.StreamHandler",
+            "formatter": 'standard',
         },
     },
-    "huey": {
-        "handlers": ["console"],
-        "level": ROOT_LOG_LEVEL,
+    'formatters': {
+        'standard': {
+            'class': 'logging.Formatter',
+            'format': '[%(asctime)s] %(levelname)s:%(name)s:%(threadName)s:%(message)s'
+        },
     },
-    "django": {
+    "root": {
         "handlers": ["console"],
         "level": ROOT_LOG_LEVEL,
     },
+    "loggers": {
+        "huey": {
+            "handlers": ["console"],
+            "level": HUEY_LOG_LEVEL,
+            "propagate": False
+        },
+    },
 }
 
 TEST_RUNNER = env("TEST_RUNNER", default="django.test.runner.DiscoverRunner")