feat: structured logging

chord_metadata_service/chord/views_data_types.py

@@ -198,9 +198,9 @@ async def dataset_data_type(request: DrfRequest, dataset_id: str, data_type: str
 
         await qs.adelete()
 
-        logger.info(f"Running cleanup after clearing data type {data_type} in dataset {dataset_id} via API")
+        await logger.ainfo(f"Running cleanup after clearing data type {data_type} in dataset {dataset_id} via API")
         n_removed = await run_all_cleanup()
-        logger.info(f"Cleanup: removed {n_removed} objects in total")
+        await logger.ainfo(f"Cleanup: removed {n_removed} objects in total")
 
         return Response(status=status.HTTP_204_NO_CONTENT)
 

chord_metadata_service/logger.py

@@ -1,7 +1,7 @@
-import logging
+import structlog
 
 __all__ = [
     "logger",
 ]
 
-logger = logging.getLogger("katsu")
+logger = structlog.getLogger("katsu")

chord_metadata_service/metadata/asgi.py

@@ -7,15 +7,15 @@
 https://docs.djangoproject.com/en/4.1/howto/deployment/asgi/
 """
 
-import logging
+import structlog
 import os
 
 from django.conf import settings
 from django.core.asgi import get_asgi_application
 
 os.environ.setdefault("DJANGO_SETTINGS_MODULE", "chord_metadata_service.metadata.settings")
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(__name__)
 
 # debugger section
 if settings.DEBUG:

chord_metadata_service/metadata/settings.py

@@ -14,6 +14,7 @@
 import sys
 import logging
 import json
+import structlog
 
 from bento_lib.service_info.types import GA4GHServiceType
 from urllib.parse import quote, urlparse
@@ -24,8 +25,6 @@
 
 load_dotenv()
 
-logging.getLogger().setLevel(logging.INFO)
-
 # Build paths inside the project like this: os.path.join(BASE_DIR, ...)
 BASE_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__)))
 
@@ -144,6 +143,7 @@
 
     'corsheaders',
     'django_filters',
+    'django_structlog',
     'rest_framework',
     'adrf',
     'drf_spectacular',
@@ -159,6 +159,7 @@
     'chord_metadata_service.authz.middleware.AuthzMiddleware',
     'django.contrib.messages.middleware.MessageMiddleware',
     'django.middleware.clickjacking.XFrameOptionsMiddleware',
+    # 'django_structlog.middlewares.RequestMiddleware',
 ]
 
 CORS_ALLOWED_ORIGINS = [orig.strip() for orig in os.environ.get("CORS_ORIGINS", "").split(";") if orig.strip()]
@@ -186,12 +187,30 @@
 ASGI_APPLICATION = 'chord_metadata_service.metadata.asgi.application'
 WSGI_APPLICATION = 'chord_metadata_service.metadata.wsgi.application'
 
+# Logging --------------------------------------------------------------------------------------------------------------
+
+STRUCTLOG_COMMON_PROCESSORS = [
+    structlog.contextvars.merge_contextvars,
+    structlog.stdlib.add_logger_name,
+    structlog.stdlib.add_log_level,
+    # format events (messages) with % using positional arguments, like Python's standard logging library:
+    structlog.stdlib.PositionalArgumentsFormatter(),
+    structlog.stdlib.ExtraAdder(),
+    structlog.processors.TimeStamper(fmt="iso"),
+]
+
 LOGGING = {
     'version': 1,
     'disable_existing_loggers': False,
     'formatters': {
         'console': {
-            'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
+            '()': structlog.stdlib.ProcessorFormatter,
+            'foreign_pre_chain': STRUCTLOG_COMMON_PROCESSORS,
+            'processors': [
+                structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+                structlog.dev.ConsoleRenderer(),
+            ],
+            # 'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
         },
     },
     'handlers': {
@@ -205,13 +224,43 @@
             'level': LOG_LEVEL,
             'handlers': ['console'],
         },
+        'asyncio': {
+            'handlers': [],
+            'propogate': True,
+        },
+        'daphne': {
+            # suppress daphne's DEBUG log spam
+            'level': 'INFO',
+            'handlers': [],
+            'propogate': True,
+        },
+        'daphne.server': {'handlers': [], 'propogate': True},
+        'django': {'handlers': [], 'propogate': True},
+        # 'django.channels.server': {
+        #     'handlers': [],
+        #     'propogate': False,
+        # },
+        'django.request': {'handlers': [], 'propogate': True},
+        'katsu': {
+            # 'level': LOG_LEVEL,
+            'handlers': [],
+            'propogate': True,
+        }
     },
 }
 
+structlog.configure(
+    processors=STRUCTLOG_COMMON_PROCESSORS + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
+    logger_factory=structlog.stdlib.LoggerFactory(),
+    cache_logger_on_first_use=True,
+)
+
 # if we are running the test suite, only log CRITICAL messages
 if len(sys.argv) > 1 and sys.argv[1] == 'test':
     logging.disable(logging.CRITICAL)
 
+# ----------------------------------------------------------------------------------------------------------------------
+
 
 # function to read postgres password file
 def get_secret(path):

chord_metadata_service/metadata/wsgi.py

@@ -7,15 +7,15 @@
 https://docs.djangoproject.com/en/4.1/howto/deployment/wsgi/
 """
 
-import logging
+import structlog
 import os
 
 from django.conf import settings
 from django.core.wsgi import get_wsgi_application
 
 os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'chord_metadata_service.metadata.settings')
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(__name__)
 
 # debugger section
 if settings.DEBUG:

chord_metadata_service/patients/api_views.py

@@ -325,26 +325,30 @@ async def get(self, request, *_args, **_kwargs):
             authz_middleware.mark_authz_done(request)
             return Response(dres.NO_PUBLIC_DATA_AVAILABLE, status=status.HTTP_404_NOT_FOUND)
         except ValidationError as e:
-            logger.info(f"Public individuals endpoint recieved validation error: {e} ({repr(discovery_scope)})")
+            await logger.ainfo(f"Public individuals endpoint recieved validation error: {e} ({repr(discovery_scope)})")
             authz_middleware.mark_authz_done(request)
             return Response(errors.bad_request_error(
                 *(e.error_list if hasattr(e, "error_list") else e.error_dict.items()),
             ), status=status.HTTP_400_BAD_REQUEST)
 
         ind_qct = thresholded_count(await filtered_qs.acount(), discovery, dt_perms_pheno)
+        threshold = get_threshold(discovery, dt_perms_pheno)
+
+        # structured event logging for public search: embed search details
+        await logger.ainfo(
+            "public individuals search",
+            queried_fields=queried_fields,
+            individual_count=ind_qct,
+            threshold=threshold,
+            sub_threshold=ind_qct <= threshold,
+        )
 
         if ind_qct == 0 and not perm_pheno_query_data:
             # 0 count means insufficient data if we only have counts permissions, but means a true 0 if we have full
             # data permissions.
-            logger.info(
-                f"Public individuals endpoint queried fields {queried_fields} which resulted in "
-                f"sub-threshold count: {ind_qct} <= {get_threshold(discovery, dt_perms_pheno)} "
-                f"({repr(discovery_scope)})")
             authz_middleware.mark_authz_done(request)
             return Response(dres.INSUFFICIENT_DATA_AVAILABLE)
 
-        logger.info(f"Public individuals search queried fields {queried_fields}, resulting in {ind_qct} individuals")
-
         (tissues_count, sampled_tissues), (experiments_count, experiment_types) = await asyncio.gather(
             individual_biosample_tissue_stats(filtered_qs, discovery, dt_perms_pheno),
             individual_experiment_type_stats(filtered_qs, discovery, dt_perms_exp),

pyproject.toml

@@ -53,6 +53,7 @@ uritemplate = "^4.1.1"
 pyhumps = "^3.8.0"
 adrf = "^0.1.7"
 referencing = "^0.32.1"
+django-structlog = "^9.0.0"
 
 [tool.poetry.group.dev.dependencies]
 coverage = "^7.4.0"