From efce2fefe11bcb5d50f46f3a88818b7931209802 Mon Sep 17 00:00:00 2001 From: Konrad Rokicki Date: Fri, 31 Jul 2026 17:13:46 -0400 Subject: [PATCH 1/2] Log each request once, not twice AccessLogMiddleware logs every request with the authenticated username and duration, and Uvicorn's own uvicorn.access logger logged it again without them. Uvicorn's --no-access-log suppresses the second copy, but it has to be repeated on every launch command and three of six were missing it: dev-launch-remote, prod-launch-remote, and dev_launch.py. prod-launch-remote is the one that serves data, so every chunk a viewer pulled was logged twice. The app now silences the logger it replaces, next to where the middleware is installed, so no launcher has to remember. This runs the same two lines Uvicorn's own access_log=False does (config.py: clear handlers, stop propagation), and both HTTP protocol implementations gate on access_logger.hasHandlers() before building the record -- so this takes the identical fast path, with no LogRecord constructed per request. That makes the remaining --no-access-log flags and access_log=False kwargs exactly redundant, so they're removed: one mechanism instead of a flag that was already unevenly applied. Uvicorn configures logging before importing the app, in --reload and --workers subprocesses too, so the app-side call always wins. Verified against a launcher that lacked the flag: two access lines before, one after, zero in Uvicorn's format, and Uvicorn's lifecycle logs (startup, shutdown) untouched since only uvicorn.access is silenced. Co-Authored-By: Claude Opus 5 (1M context) --- fileglancer/cli.py | 1 - fileglancer/log.py | 19 +++++++++++++++++++ fileglancer/server.py | 9 +++++---- pyproject.toml | 4 ++-- 4 files changed, 26 insertions(+), 7 deletions(-) diff --git a/fileglancer/cli.py b/fileglancer/cli.py index dd99b2500..6bff4efdb 100644 --- a/fileglancer/cli.py +++ b/fileglancer/cli.py @@ -194,7 +194,6 @@ def start(host, port, reload, workers, ssl_keyfile, ssl_certfile, 'app': 'fileglancer.server:app', 'host': host, 'port': port, - 'access_log': False, 'proxy_headers': True, 'forwarded_allow_ips': '*', 'timeout_keep_alive': timeout_keep_alive diff --git a/fileglancer/log.py b/fileglancer/log.py index 3e471e714..6039e3409 100644 --- a/fileglancer/log.py +++ b/fileglancer/log.py @@ -5,6 +5,7 @@ It replaces Uvicorn's default access logger to provide more detailed logging with application-level authentication context. """ +import logging import time from typing import Callable @@ -17,6 +18,24 @@ from fileglancer.settings import Settings +def disable_uvicorn_access_log(): + """Silence Uvicorn's own access logger, which AccessLogMiddleware replaces. + + Left enabled, every request is logged twice: once here with the username and + duration, once by Uvicorn without them. Uvicorn's ``--no-access-log`` does + the same thing from the outside, but it has to be remembered on every launch + command, and it was missing from several. Doing it where the middleware is + installed covers any way the app is started. + + Matches what Uvicorn's own ``access_log=False`` does. Safe to call more than + once, and safe at import time: Uvicorn configures logging before it imports + the app, including in each --reload/--workers subprocess. + """ + access_logger = logging.getLogger("uvicorn.access") + access_logger.handlers = [] + access_logger.propagate = False + + class AccessLogMiddleware(BaseHTTPMiddleware): """ Middleware that logs HTTP access information with username when available. diff --git a/fileglancer/server.py b/fileglancer/server.py index 28705a2a4..daf66ab15 100644 --- a/fileglancer/server.py +++ b/fileglancer/server.py @@ -42,7 +42,7 @@ from fileglancer.issues import create_jira_ticket, get_jira_ticket_details, delete_jira_ticket from fileglancer.utils import format_timestamp, guess_content_type, parse_range_header, make_etag, parse_http_date_to_epoch from fileglancer.filestore import Filestore, RootCheckError -from fileglancer.log import AccessLogMiddleware +from fileglancer.log import AccessLogMiddleware, disable_uvicorn_access_log from fileglancer.worker_pool import ( WorkerPool, WorkerError, WorkerDead, prepare_worker_request) from fileglancer.user_worker import serialize_job_for_worker @@ -571,8 +571,10 @@ def mask_password(url: str) -> str: app = FastAPI(lifespan=lifespan) # Add custom access log middleware - # This logs HTTP access information with authenticated username + # This logs HTTP access information with authenticated username, and + # supersedes Uvicorn's access log rather than adding to it. app.add_middleware(AccessLogMiddleware, settings=settings) + disable_uvicorn_access_log() # Attach an S3-style x-amz-request-id header to data-link (/files/) responses, # carrying over the feature added in x2s3 1.3.0 (which only applies it within @@ -2748,5 +2750,4 @@ async def serve_spa(full_path: str = ""): if __name__ == "__main__": import uvicorn - # Disable Uvicorn's default access logger since we use custom middleware - uvicorn.run(app, host="0.0.0.0", port=8000, lifespan="on", access_log=False) + uvicorn.run(app, host="0.0.0.0", port=8000, lifespan="on") diff --git a/pyproject.toml b/pyproject.toml index 301566f7c..7f066c8a2 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -144,14 +144,14 @@ node-prettier-write = "cd frontend && npx prettier --list-different --write '**/ node-check = "cd frontend && npx tsc --noEmit -p tsconfig.app.json" node-install-ui-tests = "npm --prefix frontend/ui-tests install" test-ui = { cmd = "npm --prefix frontend/ui-tests run test ", depends-on = ["node-install-ui-tests"] } -test-launch = "pixi run uvicorn fileglancer.server:app --no-access-log --port 7879" +test-launch = "pixi run uvicorn fileglancer.server:app --port 7879" dev-install = { depends-on = ["node-build", "pip-install"] } dev-watch = { cmd = "cd frontend && NODE_ENV=development npm run watch" } storybook = { cmd = "npm run storybook", cwd = "frontend" } storybook-build = { cmd = "npm run build-storybook", cwd = "frontend" } dev-vite = { cmd = "cd frontend && npx vite" } dev-vite-remote = { cmd = "cd frontend && SSL_KEYFILE=/opt/certs/cert.key SSL_CERTFILE=/opt/certs/cert.crt npx vite" } -dev-launch = "pixi run uvicorn fileglancer.server:app --no-access-log --port 7878 --reload" +dev-launch = "pixi run uvicorn fileglancer.server:app --port 7878 --reload" debug-launch = "fileglancer debug" dev-launch-remote = "pixi run uvicorn fileglancer.server:app --host 0.0.0.0 --port 7878 --reload --ssl-keyfile /opt/certs/cert.key --ssl-certfile /opt/certs/cert.crt" prod-launch-remote = "pixi run uvicorn fileglancer.server:app --workers 10 --host 0.0.0.0 --port 7878 --ssl-keyfile /opt/certs/cert.key --ssl-certfile /opt/certs/cert.crt" From 883d56e6b9a5dd11b0d724ce4dfce4560e832d3a Mon Sep 17 00:00:00 2001 From: Konrad Rokicki Date: Fri, 31 Jul 2026 17:21:23 -0400 Subject: [PATCH 2/2] Log the request target as sent, not percent-decoded The access log used request.url.path, which is built from scope["path"] and so is percent-decoded per the ASGI spec. A filename containing a literal '%' was sent as '%25' and logged as '%', so the line no longer round-tripped to the request that was actually made -- visible as a mismatch against Uvicorn's own access log, which reports the raw target. Log raw_path instead, falling back to the decoded path since ASGI marks raw_path optional, and escape control characters in both the path and the query string. The escaping is not redundant: Starlette's URL drops CR/LF because urlsplit strips them, but ESC and '|' survive, and both are client-controlled text landing in a log line -- ESC can recolour a terminal tailing it, and '|' is loguru's own field separator. The injection test drives a hand-built ASGI scope rather than TestClient, since httpx normalizes control characters away and cannot express the request being defended against. Co-Authored-By: Claude Opus 5 (1M context) --- fileglancer/log.py | 23 ++++++++++-- tests/test_log.py | 88 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 109 insertions(+), 2 deletions(-) create mode 100644 tests/test_log.py diff --git a/fileglancer/log.py b/fileglancer/log.py index 6039e3409..ad8011428 100644 --- a/fileglancer/log.py +++ b/fileglancer/log.py @@ -18,6 +18,17 @@ from fileglancer.settings import Settings +def _log_safe(value: str) -> str: + """Escape anything in client-controlled text that could disturb a log line. + + Turns control characters into their escapes, so a request target can't add + lines, recolour a terminal tailing the log, or smuggle loguru's '|' field + separator into a field. Ordinary percent-encoded paths pass through + unchanged. + """ + return value.encode("unicode_escape").decode("ascii") + + def disable_uvicorn_access_log(): """Silence Uvicorn's own access logger, which AccessLogMiddleware replaces. @@ -79,16 +90,24 @@ async def dispatch(self, request: Request, call_next: Callable) -> Response: # Get HTTP version from scope http_version = request.scope.get("http_version", "1.1") + # Log the target as the client sent it. scope["path"] is percent-decoded + # per the ASGI spec, so a filename containing a literal '%' (sent as + # '%25') logs as '%' and the line no longer round-trips to the request + # that was made. raw_path is the encoded form, which is also what + # Uvicorn's own access log reports. + raw_path = request.scope.get("raw_path") + path = raw_path.decode("latin-1") if raw_path else request.url.path + # Format log message in a standard access log format # Example: 192.168.1.100:54321 [username] "GET /api/files HTTP/1.1" 200 - 45.23ms log_message = ( f"{client_host}:{client_port} [{username}] " - f'"{request.method} {request.url.path}' + f'"{request.method} {_log_safe(path)}' ) # Add query string if present if request.url.query: - log_message += f"?{request.url.query}" + log_message += f"?{_log_safe(request.url.query)}" log_message += ( f' HTTP/{http_version}" ' diff --git a/tests/test_log.py b/tests/test_log.py new file mode 100644 index 000000000..d6a46e632 --- /dev/null +++ b/tests/test_log.py @@ -0,0 +1,88 @@ +"""Tests for the access log middleware.""" + +import asyncio + +from fastapi import FastAPI +from fastapi.testclient import TestClient +from loguru import logger + +from fileglancer.log import AccessLogMiddleware +from fileglancer.settings import Settings + + +def _app_and_lines(): + """A minimal app behind AccessLogMiddleware, plus the lines it logs.""" + app = FastAPI() + app.add_middleware(AccessLogMiddleware, settings=Settings()) + + @app.get("/api/content/{rest:path}") + async def content(rest: str): + return {"ok": True} + + lines = [] + sink_id = logger.add(lambda msg: lines.append(msg), format="{message}") + return app, lines, sink_id + + +def test_percent_encoding_is_logged_as_sent(): + """The logged path keeps the client's encoding instead of decoding it. + + A decoded path no longer round-trips to the request that was actually made, + which matters when the difference is a literal '%' in a filename. + """ + app, lines, sink_id = _app_and_lines() + try: + with TestClient(app) as client: + client.get("/api/content/share/img_1%25_0.2%25.zarr") + finally: + logger.remove(sink_id) + + assert len(lines) == 1, lines + assert "img_1%25_0.2%25.zarr" in lines[0], lines[0] + + +def test_control_characters_never_reach_the_log(): + """Control characters in a decoded path must not reach the log line. + + Driven through a hand-built ASGI scope rather than TestClient, because httpx + normalizes control characters away and cannot express what a hostile client + sends. Over the wire, '%1B' in the target becomes a real ESC in + scope["path"]. Starlette's URL happens to drop CR/LF (urlsplit strips them) + but ESC and '|' survive it, so the escaping here is doing real work: ESC can + recolour a terminal tailing the log, and '|' is loguru's field separator. + """ + app, lines, sink_id = _app_and_lines() + scope = { + "type": "http", + "asgi": {"version": "3.0", "spec_version": "2.3"}, + "http_version": "1.1", + "method": "GET", + "scheme": "http", + # What the server hands us: path decoded, raw_path as sent. + "path": "/api/content/x\n\x1b[2J2026-01-01 | INFO | FORGED", + "raw_path": b"/api/content/x%0A%1B[2J2026-01-01%20|%20INFO%20|%20FORGED", + "query_string": b"", + "headers": [(b"host", b"testserver")], + "client": ("10.0.0.1", 1234), + "server": ("testserver", 80), + "root_path": "", + } + + async def receive(): + return {"type": "http.request", "body": b"", "more_body": False} + + async def send(message): + pass + + try: + asyncio.run(app(scope, receive, send)) + finally: + logger.remove(sink_id) + + assert len(lines) == 1, lines + logged = lines[0] + # loguru's sink appends one trailing newline; the message must add none. + assert logged.rstrip("\n").count("\n") == 0, repr(logged) + assert "\x1b" not in logged, repr(logged) + # The encoded form is what gets logged, so both stay inert. + assert "%0A" in logged and "%1B" in logged, repr(logged)