Merge branch '13-structured-logging' into 'main'

use structlog

See merge request !12

configure.sh

@@ -6,6 +6,7 @@
     ENABLE_HTTP_ACCESS=${ENABLE_HTTP_ACCESS:="false"}
     # Configure instance
     sed -e "s/'disable_existing_loggers': True,/'disable_existing_loggers': False,/" -i pvs_instance/settings.py
+    sed -e "s/import os/import os\nimport structlog/" -i pvs_instance/settings.py
     HANDLERS="'handlers': {\n
         'null': {\n
             'level':'DEBUG',\n
@@ -14,7 +15,7 @@
         'console': {\n
             'level': 'DEBUG' if DEBUG else 'INFO',\n
             'class': 'logging.StreamHandler',\n
-            'formatter': 'verbose' if DEBUG else 'simple',\n
+            'formatter': 'json',\n
             'filters': [],\n
         },\n
     },"
@@ -25,8 +26,15 @@
             'propagate': False,\n
         },
     }"
+    FORMATTERS="'formatters': {\n
+        'json': {\n
+            '()': structlog.stdlib.ProcessorFormatter,\n
+            'processor': structlog.dev.ConsoleRenderer() if DEBUG else structlog.processors.JSONRenderer(),
+        },
+    },"
     sed -e "/^    'handlers': {$/,/^    },$/c `echo ${HANDLERS}`" -i pvs_instance/settings.py
     sed -e "/^    'loggers': {$/,/^    }$/c `echo ${LOGGERS}`" -i pvs_instance/settings.py
+    sed -e "/^    'formatters': {$/,/^    },$/c `echo ${FORMATTERS}`" -i pvs_instance/settings.py
 
     sed -e "s,http_service_url=http://localhost:8000/ows,http_service_url=${APACHE_ALIAS}/ows," -i pvs_instance/conf/eoxserver.conf
     sed -e "s/resampling_method=average/resampling_method=near/" -i pvs_instance/conf/eoxserver.conf

gunicorn.conf.py

@@ -11,6 +11,12 @@ worker_class = 'sync'
 
 # logging
 accesslog = '-'
+access_log_format = '{"remote_address":"%(h)s",' \
+    '"response_code":"%(s)s","request_method":"%(m)s",' \
+    '"request_path":"%(U)s","request_querystring":"%(q)s",' \
+    '"request_time":"%(M)s","response_length":"%(B)s",' \
+    '"user":"%(u)s","status_line":"%(r)s","referer":"%(r)s",' \
+    '"user_agent":"%(a)s"}'
 errorlog = '-'
 loglevel = 'warning'
 disable_redirect_access_to_syslog = True

registrar/backend/eoxserver.py

@@ -7,7 +7,7 @@ Contains implementations for different backends where data may be registered
 """
 import os
 import sys
-import logging
+import structlog
 from typing import List, TYPE_CHECKING, Optional, TypedDict, cast
 import json
 from urllib.parse import urlparse
@@ -26,7 +26,7 @@ from ..source import Source, LocalSource, S3Source, SwiftSource
 from .abc import ItemBackend
 
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 class AssetsToCoverageMapping(TypedDict):
@@ -207,9 +207,9 @@ class EOxServerBackend(ItemBackend):
             storage_name = storage.name
 
         if created_storage_auth:
-            logger.info(f"Created storage auth for {source.name}")
+            logger.info("Created storage auth", source=source.name)
         if created_storage:
-            logger.info(f"Created storage for {source.name}")
+            logger.info("Created storage for", source=source.name)
 
         return [storage_name] if storage_name else []
 
@@ -266,9 +266,9 @@ class EOxServerBackend(ItemBackend):
             product_type_obj = models.ProductType.objects.get(name=product_type["name"])
 
         if created:
-            logger.info(f"Created Product Type {product_type_obj}")
+            logger.info("Created Product Type" , product_type_obj=product_type_obj)
         else:
-            logger.info(f"Using existing Product Type {product_type_obj}")
+            logger.info("Using existing Product Type", product_type_obj=product_type_obj)
 
         # resolve storage object
         if storage:
@@ -317,8 +317,8 @@ class EOxServerBackend(ItemBackend):
             service_visibility.save()
 
         logger.info(
-            f"Successfully {'replaced' if replaced else 'registered'} "
-            f"Product {product.identifier}"
+            f"Successfully {'replaced' if replaced else 'registered'} Product",
+            product=product.identifier,
         )
 
         return product
@@ -362,7 +362,7 @@ class EOxServerBackend(ItemBackend):
                 break
 
         if product_type_found:
-            logger.info(f"Registering into EOxServer for type '{product_type['name']}'")
+            logger.info("Registering into EOxServer", type=product_type['name'])
             product = self._register_with_stac(
                 source, item, replace, storage, product_type
             )
@@ -393,27 +393,29 @@ class EOxServerBackend(ItemBackend):
         # ugly, ugly hack
         from eoxserver.resources.coverages import models
 
-        try:
-            logger.info(f"Deregistering product '{identifier}'")
-            product = models.Product.objects.get(identifier=identifier)
-            grids = list(models.Grid.objects.filter(coverage__parent_product=product))
-            product.delete()
-
-            # clean up grids
-            for grid in grids:
-                grid_used = models.EOObject.objects.filter(
-                    Q(coverage__grid=grid) | Q(mosaic__grid=grid),
-                ).exists()
-                # clean up grid as well, if it is not referenced
-                # anymore but saving named (user defined) grids
-                if grid and not grid.name and not grid_used:
-                    grid.delete()
-        except models.Product.DoesNotExist:
-            logger.info(f"No product with identifier '{identifier}' found")
-            # no product found with that id
-            # return empty list
-            return None
-
-        logger.info(f"Deregistered product with identifier '{identifier}'")
+        with structlog.contextvars.bound_contextvars(indentifier=identifier):
+
+            try:
+                logger.info("Deregistering product")
+                product = models.Product.objects.get(identifier=identifier)
+                grids = list(models.Grid.objects.filter(coverage__parent_product=product))
+                product.delete()
+
+                # clean up grids
+                for grid in grids:
+                    grid_used = models.EOObject.objects.filter(
+                        Q(coverage__grid=grid) | Q(mosaic__grid=grid),
+                    ).exists()
+                    # clean up grid as well, if it is not referenced
+                    # anymore but saving named (user defined) grids
+                    if grid and not grid.name and not grid_used:
+                        grid.delete()
+            except models.Product.DoesNotExist:
+                logger.info("No product with identifier found")
+                # no product found with that id
+                # return empty list
+                return None
+
+            logger.info("Deregistered product")
         # return the deleted identifier
         return identifier

registrar/cli.py

@@ -2,6 +2,8 @@ from os.path import join, dirname
 import logging.config
 
 import click
+import structlog
+import structlog.contextvars
 import yaml
 import jsonschema
 
@@ -22,13 +24,20 @@ def setup_logging(debug=False):
         {
             "version": 1,
             "disable_existing_loggers": False,
-            "formatters": {"brief": {"format": "%(levelname)s %(name)s: %(message)s"}},
+            "formatters": {
+                "json": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processor": structlog.dev.ConsoleRenderer()
+                    if debug
+                    else structlog.processors.JSONRenderer(),
+                },
+            },
             "handlers": {
                 "console": {
                     "class": "logging.StreamHandler",
                     "level": "DEBUG" if debug else "INFO",
-                    "formatter": "brief",
-                }
+                    "formatter": "json",
+                },
             },
             "root": {
                 "handlers": ["console"],
@@ -37,6 +46,25 @@ def setup_logging(debug=False):
         }
     )
 
+    structlog.configure(
+        processors=[
+            structlog.contextvars.merge_contextvars,
+            structlog.stdlib.filter_by_level,
+            structlog.processors.TimeStamper(fmt="iso"),
+            structlog.stdlib.add_logger_name,
+            structlog.stdlib.add_log_level,
+            structlog.stdlib.PositionalArgumentsFormatter(),
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+            structlog.processors.UnicodeDecoder(),
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        context_class=structlog.threadlocal.wrap_dict(dict),
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
 
 def validate_config(config):
     with open(join(dirname(__file__), "config-schema.yaml")) as f:

registrar/daemon.py

@@ -6,13 +6,13 @@ Contains the daemon functions for the registrar
 
 """
 
-import logging
+import structlog
 from typing import Callable, Dict
 
 import redis
 
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 # callback declaration: callable with 'config', item and replace
@@ -52,8 +52,8 @@ def run_daemon(
     queue_names = list(handlers.keys())
     logger.debug(
         f"waiting on items on redis "
-        f"queue{'s' if len(queue_names) > 1 else ''} "
-        f"{', '.join(queue_names)}..."
+        f"queue{'s' if len(queue_names) > 1 else ''}",
+        queues=queue_names,
     )
 
     while True:

registrar/post_handlers.py

@@ -8,7 +8,7 @@ Contains different handlers that trigger post registration
 import os.path
 import textwrap
 from datetime import datetime
-import logging
+import structlog
 from typing import TYPE_CHECKING
 from xml.sax.saxutils import escape
 
@@ -17,7 +17,7 @@ if TYPE_CHECKING:
 
 from .utils import isoformat
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 class ReportingPostHandler:
@@ -36,7 +36,7 @@ class ReportingPostHandler:
         timestamp = inserted.strftime("%Y%m%dT%H%M%S")
         sanitized_filename = self.sanitize_path(f"item_{timestamp}_{item.id}.xml")
         filename = os.path.join(self.reporting_dir, sanitized_filename)
-        logger.info(f"Generating report for product {item.id} at {filename}")
+        logger.info("Generating report", product=item.id, filename=filename)
 
         identifier = escape(item.id)
         availability_time = escape(isoformat(inserted))

registrar/registrar.py

@@ -5,10 +5,11 @@ registrar.py
 Contains all functions relevant for registration
 
 """
-import logging
 from typing import Optional
 import json
 
+import structlog
+import structlog.contextvars
 from pystac import Item
 
 from .source import get_source, get_source_from_path
@@ -16,7 +17,7 @@ from .backend import get_backends, get_path_backends
 from .exceptions import RegistrationError
 from .utils import import_by_path
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 def register_item(config: dict, value: str, replace: bool = False):
@@ -33,34 +34,36 @@ def register_item(config: dict, value: str, replace: bool = False):
                            not turned on
     """
     item = Item.from_dict(json.loads(value))
-    source = get_source(config, item)
-    logger.info(f"Handling '{item!r}'.")
-
-    for pre_handler in get_pre_handlers(config):
-        pre_handler(config, item)
-
-    try:
-        for backend in get_backends(config):
-            if backend.item_exists(source, item):
-                if replace:
-                    logger.info(f"Replacing '{item!r}'.")
-                    backend.register_item(source, item, replace=True)
+    with structlog.contextvars.bound_contextvars(item=item):
+        logger.info("Handling item")
+
+        source = get_source(config, item)
+
+        for pre_handler in get_pre_handlers(config):
+            pre_handler(config, item)
+
+        try:
+            for backend in get_backends(config):
+                if backend.item_exists(source, item):
+                    if replace:
+                        logger.info("Replacing item")
+                        backend.register_item(source, item, replace=True)
+                    else:
+                        raise RegistrationError(f"Object {item!r} is already registered")
                 else:
-                    raise RegistrationError(f"Object {item!r} is already registered")
-            else:
-                logger.info(f"Registering '{item!r}'.")
-                backend.register_item(source, item, replace=False)
-    except Exception as e:
-        for error_handler in get_error_handlers(config):
-            error_handler(config, item, e)
-        raise
-    else:
-        for post_handler in get_post_handlers(config):
-            post_handler(config, item)
-
-        logger.info(
-            f"Successfully {'replaced' if replace else 'registered'} " f"'{item!r}'"
-        )
+                    logger.info("Registering item")
+                    backend.register_item(source, item, replace=False)
+        except Exception as e:
+            for error_handler in get_error_handlers(config):
+                error_handler(config, item, e)
+            raise
+        else:
+            for post_handler in get_post_handlers(config):
+                post_handler(config, item)
+
+            logger.info(
+                f"Successfully {'replaced' if replace else 'registered'}"
+            )
 
 
 def register_path(config: dict, path: str, replace: bool = False):

registrar/source.py

@@ -11,7 +11,7 @@ from os.path import normpath, join, isabs
 import shutil
 from glob import glob
 from fnmatch import fnmatch
-import logging
+import structlog
 from typing import TYPE_CHECKING, Optional
 from abc import ABC, abstractmethod
 from urllib.parse import urlparse
@@ -29,7 +29,7 @@ if TYPE_CHECKING:
 from swiftclient.service import SwiftService
 
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 class RegistrationError(Exception):
@@ -293,7 +293,7 @@ class S3Source(Source):
             glob_patterns = [glob_patterns]
 
         bucket, key = self.get_container_and_path(path)
-        logger.info(f"Listing S3 files for bucket {bucket} and prefix {key}")
+        logger.info("Listing S3 files", bucket=bucket, prefix=key)
         response = self.client.list_objects_v2(
             Bucket=bucket,
             Prefix=key,
@@ -312,7 +312,10 @@ class S3Source(Source):
     def get_file(self, path: str, target_path: str):
         bucket, key = self.get_container_and_path(path)
         logger.info(
-            f"Retrieving file from S3 {bucket}/{key} to be stored at {target_path}"
+            "Retrieving file from S3",
+            bucket=bucket,
+            key=key,
+            target_path=target_path,
         )
         self.client.download_file(bucket, key, target_path)
 

registrar/xml.py

@@ -3,7 +3,7 @@ from os.path import join, basename
 from tempfile import gettempdir
 from dataclasses import dataclass, field
 from typing import Optional, Callable, Any
-import logging
+import structlog
 
 import lxml.etree
 
@@ -11,7 +11,7 @@ from .source import Source
 from .exceptions import RegistrationError
 
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 def read_xml(source: Source, path: str) -> lxml.etree._ElementTree:

requirements.txt

@@ -6,5 +6,6 @@ pyyaml<6.0
 jsonschema<5.0
 boto3<2.0
 django-cors-headers<4.0
+django-structlog==2.2.0
 pystac<2.0
 http-access==0.1.3