diff --git a/cista/app.py b/cista/app.py index cadda3d..89aa1cc 100644 --- a/cista/app.py +++ b/cista/app.py @@ -13,7 +13,7 @@ from blake3 import blake3 from mediapreview.office import close_oo_client, log_reachable_info from mediapreview.pool import shutdown_preview_workers, start_preview_workers from sanic import Sanic, empty, raw, redirect -from sanic.exceptions import Forbidden, NotFound +from sanic.exceptions import Forbidden, NotFound, RequestCancelled from sanic.log import logger from setproctitle import setproctitle from stream_zip import ZIP_AUTO, stream_zip @@ -35,6 +35,7 @@ from cista.sanic_logging import ( configure_access_logging, configure_main_logging, format_access_log, + reset_sanic_log_levels, ) from cista.sanic_logging import logger as access_logger from cista.util.apphelpers import handle_sanic_exception @@ -124,11 +125,28 @@ app.blueprint(fileserver.bp) app.exception(Exception)(handle_sanic_exception) +@app.exception(asyncio.CancelledError) +async def request_cancelled(req, e): + """Request cancelled mid-flight (client disconnect or server shutdown). + + Sanic wraps this as RequestCancelled (client disconnect only) — a + BaseException, so the generic Exception handler above never sees it — and + its default handler renders a 500 error page. Report 499 for client + disconnects and 503 for server-side cancellation instead; no traceback + (quiet=True), since there is nothing to fix. The connection is usually + already gone. + """ + if not getattr(req.ctx, "log_extra", None): + req.ctx.log_extra = "cancelled" + return empty(499 if isinstance(e, RequestCancelled) else 503) + + setproctitle("cista-main") @app.before_server_start async def main_start(app): + reset_sanic_log_levels() config.load_config() onlyoffice.configure() setproctitle(f"cista {config.config.path.name}") diff --git a/cista/preview.py b/cista/preview.py index 5a9ea91..f608938 100644 --- a/cista/preview.py +++ b/cista/preview.py @@ -6,6 +6,7 @@ Sanic with auth, etag negotiation and the in-memory response cache. """ import asyncio +import re import urllib.parse from pathlib import PurePosixPath from urllib.parse import unquote @@ -38,6 +39,21 @@ bp = Blueprint("preview", url_prefix="/preview") _preview_cache = PreviewCache(capacity=500) +def _shorten_error(detail: str) -> str: + """Shorten an upstream backend error for the single-line access log. + + Backend errors arrive verbatim from ffmpeg/pyvips/pymupdf and often carry + an '[Errno N]' prefix, the input file path, and multi-line library noise — + all redundant with the URL already in the log line. Keep the first line, + drop the bracket prefix, and cut at the first ': ' separator. + """ + lines = detail.splitlines() + if not lines: + return "" + first_line = re.sub(r"^\[[^\]]*\]\s*", "", lines[0].strip()) + return first_line.split(": ", 1)[0] + + @bp.on_request async def verify_preview(request): """Verify access to preview routes.""" @@ -125,8 +141,16 @@ async def preview(req, path): if captured: detail = captured.splitlines()[0] # The worker already logged the failure (with traceback where the - # error occurred) — annotate the access log instead of re-logging. - req.ctx.log_extra = e.backend or detail + # error occurred) — annotate the access log instead of re-logging, + # with a shortened reason. In dev mode, print the full error too. + backend = e.backend or _expected_preview_backend(filepath) + if req.app.debug: + full = detail + if e.stderr and e.stderr.strip() not in detail: + full = f"{detail}\n{e.stderr.strip()}" + logger.warning("[%s] preview failed: %s", backend, full.strip()) + short = _shorten_error(detail) + req.ctx.log_extra = f"{backend}: {short}" if short else backend return empty(422) except asyncio.CancelledError: # Server shutdown or client disconnect: the connection is being torn diff --git a/cista/sanic_logging.py b/cista/sanic_logging.py index adf9d8b..df68d19 100644 --- a/cista/sanic_logging.py +++ b/cista/sanic_logging.py @@ -294,7 +294,23 @@ def configure_main_logging() -> None: # Patch the config defaults too, so the level survives Sanic's dictConfig. LOGGING_CONFIG_DEFAULTS["loggers"]["sanic.websockets"]["level"] = "ERROR" logging.getLogger("sanic.websockets").setLevel(logging.ERROR) + # Preview worker timeouts are already annotated in the access log extra; + # the pool's WARNING would otherwise fall to logging.lastResort, printing + # a bare message with no level prefix. + logging.getLogger("mediapreview.pool").setLevel(logging.ERROR) # Also reformat any handlers already attached (covers the initial Sanic() call) for name in ("sanic.root", "sanic.error", "sanic.server", "sanic.websockets"): for handler in logging.getLogger(name).handlers: handler.setFormatter(_EmojiFormatter()) + + +def reset_sanic_log_levels() -> None: + """Force Sanic's loggers back to INFO in debug/dev mode. + + Debug mode enables DEBUG on sanic.root at runtime + (ApplicationState.set_mode calls logger.setLevel(DEBUG)), which unleashes + useless noise like the 'Error Page:' content-negotiation messages. Call + from before_server_start so the override lands after Sanic's own setup. + """ + for name in ("sanic.root", "sanic.error", "sanic.server"): + logging.getLogger(name).setLevel(logging.INFO)