From 447a3d7d3dd85b4806484962a9e2cddbe0e73fee Mon Sep 17 00:00:00 2001 From: Dan Allan Date: Tue, 28 May 2024 14:47:50 -0400 Subject: [PATCH] Customize default uvicorn logging config to include authenticated user/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 | 9 +++++ tiled/_tests/test_cli.py | 45 ++++++++++++++++++++--- tiled/commandline/_serve.py | 55 ++++++++++++++++++++++++---- tiled/server/app.py | 15 +++++++- tiled/server/authentication.py | 2 + tiled/server/logging_config.py | 54 +++++++++++++++++++++++++++ tiled/server/principal_log_filter.py | 21 +++++++++++ 7 files changed, 188 insertions(+), 13 deletions(-) create mode 100644 tiled/server/logging_config.py create mode 100644 tiled/server/principal_log_filter.py diff --git a/CHANGELOG.md b/CHANGELOG.md index c1c4d9d6a..eeef48bc6 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/tiled/_tests/test_cli.py b/tiled/_tests/test_cli.py index f2f764a1c..8d1c20550 100644 --- a/tiled/_tests/test_cli.py +++ b/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) diff --git a/tiled/commandline/_serve.py b/tiled/commandline/_serve.py index 28faf021b..17ef6f971 100644 --- a/tiled/commandline/_serve.py +++ b/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 diff --git a/tiled/server/app.py b/tiled/server/app.py index fd4d9b0ca..1ba9dfcd6 100644 --- a/tiled/server/app.py +++ b/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", diff --git a/tiled/server/authentication.py b/tiled/server/authentication.py index c78beb84b..3a4fa5afa 100644 --- a/tiled/server/authentication.py +++ b/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 diff --git a/tiled/server/logging_config.py b/tiled/server/logging_config.py new file mode 100644 index 000000000..422689638 --- /dev/null +++ b/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, +} diff --git a/tiled/server/principal_log_filter.py b/tiled/server/principal_log_filter.py new file mode 100644 index 000000000..faf4f0fd9 --- /dev/null +++ b/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