Customize default uvicorn logging config to include authenticated use…

…r/service, correlation ID. (#750)

* Customize default uvicorn logging config to include correlation ID.

* Update CHANGELOG

* Include current principal in access logs.

* Fix regression: 'tiled serve config' defaults to no logs.

* Fix order to restore correlation ID.

* TST: Deal with color codes in log output.

* Do not log timestamp by default.

* Add --log-timestamps to opt in to timestamps.

* Test 'tiled serve config ...'

CHANGELOG.md

@@ -3,6 +3,15 @@ Write the date in place of the "Unreleased" in the case a new version is release
 
 # Changelog
 
+## Unreleased
+
+## Changed
+
+- Customized default logging configuration to include correlation ID and username
+  of authenticated user.
+- Added `--log-timestamps` CLI flag to `tiled serve ...` to opt in to including
+  timestamp prefix in log messages.
+
 ## v0.1.0b1 (2024-05-25)
 
 ### Added

tiled/_tests/test_cli.py

@@ -25,11 +25,17 @@ def scrape_server_url_from_logs(process):
     "Scrape from server logs 'Uvicorn running on https://...'"
 
     def target(queue):
-        pattern = re.compile(r"Uvicorn running on (\S*)")
+        pattern = re.compile(r"Uvicorn running on .*(http:\/\/\S+:\d+).*")
+        lines = []
         while not process.poll():
             line = process.stderr.readline()
+            lines.append(line.decode())
             if match := pattern.search(line.decode()):
                 break
+        else:
+            raise RuntimeError(
+                "Did not find server URL in log output:\n" + "\n".join(lines)
+            )
         url = match.group(1)
         queue.put(url)
 
@@ -59,9 +65,9 @@ def check_server_readiness(process):
         "--api-key secret",
     ],
 )
-def test_serve_directory(args, tmpdir):
+def test_serve_directory(args, tmp_path):
     "Test 'tiled serve directory ... with a variety of arguments."
-    with run_cli(f"tiled serve directory {tmpdir!s} --port 0 " + args) as process:
+    with run_cli(f"tiled serve directory {tmp_path!s} --port 0 " + args) as process:
         check_server_readiness(process)
 
 
@@ -72,7 +78,36 @@ def test_serve_directory(args, tmpdir):
         "--api-key secret",
     ],
 )
-def test_serve_catalog_temp(args, tmpdir):
+def test_serve_catalog_temp(args, tmp_path):
     "Test 'tiled serve catalog --temp ... with a variety of arguments."
-    with run_cli(f"tiled serve directory {tmpdir!s} --port 0 " + args) as process:
+    with run_cli(f"tiled serve directory {tmp_path!s} --port 0 " + args) as process:
+        check_server_readiness(process)
+
+
+@pytest.mark.parametrize(
+    "args",
+    [
+        "",
+    ],
+)
+def test_serve_config(args, tmp_path):
+    "Test 'tiled serve config' with a tmp config file."
+    (tmp_path / "data").mkdir()
+    (tmp_path / "config").mkdir()
+    config_filepath = tmp_path / "config" / "config.yml"
+    with open(config_filepath, "w") as file:
+        file.write(
+            f"""
+authentication:
+  allow_anonymous_access: false
+trees:
+  - path: /
+    tree: catalog
+    args:
+      uri: sqlite+aiosqlite:///{tmp_path / 'catalog.db'}
+      writable_storage: {tmp_path / 'data'}
+      init_if_not_exists: true
+"""
+        )
+    with run_cli(f"tiled serve config {config_filepath} --port 0 " + args) as process:
         check_server_readiness(process)

tiled/commandline/_serve.py

@@ -102,6 +102,9 @@ def serve_directory(
     log_config: Optional[str] = typer.Option(
         None, help="Custom uvicorn logging configuration file"
     ),
+    log_timestamps: bool = typer.Option(
+        False, help="Include timestamps in log output."
+    ),
 ):
     "Serve a Tree instance from a directory of files."
     import tempfile
@@ -199,12 +202,11 @@ def serve_directory(
 
     import anyio
     import uvicorn
-    from uvicorn.config import LOGGING_CONFIG
 
     from ..client import from_uri as client_from_uri
 
     print_admin_api_key_if_generated(web_app, host=host, port=port, force=generated)
-    log_config = log_config or LOGGING_CONFIG  # fall back to uvicorn default
+    log_config = _setup_log_config(log_config, log_timestamps)
     config = uvicorn.Config(web_app, host=host, port=port, log_config=log_config)
     server = uvicorn.Server(config)
 
@@ -339,6 +341,9 @@ def serve_catalog(
     log_config: Optional[str] = typer.Option(
         None, help="Custom uvicorn logging configuration file"
     ),
+    log_timestamps: bool = typer.Option(
+        False, help="Include timestamps in log output."
+    ),
 ):
     "Serve a catalog."
     import urllib.parse
@@ -437,9 +442,8 @@ def serve_catalog(
     print_admin_api_key_if_generated(web_app, host=host, port=port)
 
     import uvicorn
-    from uvicorn.config import LOGGING_CONFIG
 
-    log_config = log_config or LOGGING_CONFIG  # fall back to uvicorn default
+    log_config = _setup_log_config(log_config, log_timestamps)
     uvicorn.run(web_app, host=host, port=port, log_config=log_config)
 
 
@@ -487,6 +491,9 @@ def serve_pyobject(
     log_config: Optional[str] = typer.Option(
         None, help="Custom uvicorn logging configuration file"
     ),
+    log_timestamps: bool = typer.Option(
+        False, help="Include timestamps in log output."
+    ),
 ):
     "Serve a Tree instance from a Python module."
     from ..server.app import build_app, print_admin_api_key_if_generated
@@ -506,9 +513,8 @@ def serve_pyobject(
     print_admin_api_key_if_generated(web_app, host=host, port=port)
 
     import uvicorn
-    from uvicorn.config import LOGGING_CONFIG
 
-    log_config = log_config or LOGGING_CONFIG  # fall back to uvicorn default
+    log_config = _setup_log_config(log_config, log_timestamps)
     uvicorn.run(web_app, host=host, port=port, log_config=log_config)
 
 
@@ -586,6 +592,9 @@ def serve_config(
     log_config: Optional[str] = typer.Option(
         None, help="Custom uvicorn logging configuration file"
     ),
+    log_timestamps: bool = typer.Option(
+        False, help="Include timestamps in log output."
+    ),
 ):
     "Serve a Tree as specified in configuration file(s)."
     import os
@@ -623,7 +632,10 @@ def serve_config(
     # If --host is given, it overrides host in config. Same for --port and --log-config.
     uvicorn_kwargs["host"] = host or uvicorn_kwargs.get("host", "127.0.0.1")
     uvicorn_kwargs["port"] = port or uvicorn_kwargs.get("port", 8000)
-    uvicorn_kwargs["log_config"] = log_config or uvicorn_kwargs.get("log_config")
+    uvicorn_kwargs["log_config"] = _setup_log_config(
+        log_config or uvicorn_kwargs.get("log_config"),
+        log_timestamps,
+    )
 
     # This config was already validated when it was parsed. Do not re-validate.
     logger.info(f"Using configuration from {Path(config_path).absolute()}")
@@ -643,3 +655,32 @@ def serve_config(
     import uvicorn
 
     uvicorn.run(web_app, **uvicorn_kwargs)
+
+
+def _setup_log_config(log_config, log_timestamps):
+    if log_config is None:
+        from ..server.logging_config import LOGGING_CONFIG
+
+        log_config = LOGGING_CONFIG
+
+    if log_timestamps:
+        import copy
+
+        log_config = copy.deepcopy(log_config)
+        try:
+            log_config["formatters"]["access"]["format"] = (
+                "[%(asctime)s.%(msecs)03dZ] "
+                + log_config["formatters"]["access"]["format"]
+            )
+            log_config["formatters"]["default"]["format"] = (
+                "[%(asctime)s.%(msecs)03dZ] "
+                + log_config["formatters"]["default"]["format"]
+            )
+        except KeyError:
+            typer.echo(
+                "The --log-timestamps option is only applicable with a logging "
+                "configuration that, like the default logging configuration, has "
+                "formatters 'access' and 'default'."
+            )
+            raise typer.Abort()
+    return log_config

tiled/server/app.py

@@ -1,5 +1,6 @@
 import asyncio
 import collections
+import contextvars
 import logging
 import os
 import secrets
@@ -38,7 +39,7 @@
 from ..media_type_registration import (
     compression_registry as default_compression_registry,
 )
-from ..utils import SHARE_TILED_PATH, Conflicts, UnsupportedQueryType
+from ..utils import SHARE_TILED_PATH, Conflicts, SpecialUsers, UnsupportedQueryType
 from ..validation_registration import validation_registry as default_validation_registry
 from . import schemas
 from .authentication import get_current_principal
@@ -77,6 +78,10 @@
 logger.addHandler(handler)
 
 
+# This is used to pass the currently-authenticated principal into the logger.
+current_principal = contextvars.ContextVar("current_principal")
+
+
 def custom_openapi(app):
     """
     The app's openapi method will be monkey-patched with this.
@@ -865,6 +870,14 @@ async def capture_metrics_prometheus(request: Request, call_next):
             # An exception above would have triggered an early exit.
             return response
 
+    @app.middleware("http")
+    async def current_principal_logging_filter(request: Request, call_next):
+        request.state.principal = SpecialUsers.public
+        response = await call_next(request)
+        response.__class__ = PatchedStreamingResponse  # tolerate memoryview
+        current_principal.set(request.state.principal)
+        return response
+
     app.add_middleware(
         CorrelationIdMiddleware,
         header_name="X-Tiled-Request-ID",

tiled/server/authentication.py

@@ -373,6 +373,8 @@ async def get_current_principal(
             ),
             headers=headers_for_401(request, security_scopes),
         )
+    # This is used to pass the currently-authenticated principal into the logger.
+    request.state.principal = principal
     return principal
 
 

tiled/server/logging_config.py

@@ -0,0 +1,54 @@
+LOGGING_CONFIG = {
+    "disable_existing_loggers": False,
+    "filters": {
+        "principal": {
+            "()": "tiled.server.principal_log_filter.PrincipalFilter",
+        },
+        "correlation_id": {
+            "()": "asgi_correlation_id.CorrelationIdFilter",
+            "default_value": "-",
+            "uuid_length": 16,
+        },
+    },
+    "formatters": {
+        "access": {
+            "()": "uvicorn.logging.AccessFormatter",
+            "datefmt": "%Y-%m-%dT%H:%M:%S",
+            "format": (
+                "[%(correlation_id)s] "
+                '%(client_addr)s (%(principal)s) - "%(request_line)s" '
+                "%(status_code)s"
+            ),
+            "use_colors": True,
+        },
+        "default": {
+            "()": "uvicorn.logging.DefaultFormatter",
+            "datefmt": "%Y-%m-%dT%H:%M:%S",
+            "format": "[%(correlation_id)s] %(levelprefix)s %(message)s",
+            "use_colors": True,
+        },
+    },
+    "handlers": {
+        "access": {
+            "class": "logging.StreamHandler",
+            "filters": ["principal", "correlation_id"],
+            "formatter": "access",
+            "stream": "ext://sys.stdout",
+        },
+        "default": {
+            "class": "logging.StreamHandler",
+            "filters": ["correlation_id"],
+            "formatter": "default",
+            "stream": "ext://sys.stderr",
+        },
+    },
+    "loggers": {
+        "uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},
+        "uvicorn.error": {
+            "handlers": ["default"],
+            "level": "INFO",
+            "propagate": False,
+        },
+    },
+    "version": 1,
+}

tiled/server/principal_log_filter.py

@@ -0,0 +1,21 @@
+from logging import Filter, LogRecord
+
+from ..utils import SpecialUsers
+from .app import current_principal
+
+
+class PrincipalFilter(Filter):
+    """Logging filter to attach username or Service Principal UUID to LogRecord"""
+
+    def filter(self, record: LogRecord) -> bool:
+        principal = current_principal.get()
+        if isinstance(principal, SpecialUsers):
+            short_name = f"{principal.value}"
+        elif principal.type == "service":
+            short_name = f"service:{principal.uuid}"
+        else:  # principal.type == "user"
+            short_name = ",".join(
+                f"'{identity.id}'" for identity in principal.identities
+            )
+        record.principal = short_name
+        return True