Log each request once

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

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,35 @@
 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.
+
+    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.
@@ -60,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}" '

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")

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"

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)