diff --git a/CHANGELOG.md b/CHANGELOG.md index 05f34b0..f83cfc7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,35 @@ All notable changes to this project are documented here. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [0.23.0] - 2026-06-20 + +### Added + +- **Durable vLLM logs that survive restart/recreate (#50).** When a vLLM + container restarted, its `docker logs` — and any EngineCore crash trace — were + lost, which blocked root-causing #50 for lack of data. `model init` now + scaffolds `mg-logwrap.sh`, bind-mounted as each vLLM service's entrypoint: it + tees stdout+stderr to a per-boot file `-.log` under a + host-mounted log dir (`${MODEL_GEAR_LOG_DIR:-/logs}` → `/logs/model-gear`), + then `exec`s the real command so vLLM stays the signal target (graceful + shutdown) and the exit code (and `restart:` policy) are unchanged. Teeing at the + process-I/O level captures **both** Python tracebacks and native CUDA/C++ aborts; + if logging can't be set up it falls back to a plain `exec` and never blocks + serving. The crash boot is preserved as its own file. Wired into the single-model + and fleet (`primary`/`embed`/`rerank`) compose templates. See + `docs/durable-logs.md`. +- **`model logs`** — new read-only verb to list/tail the durable logs, reading the + host files directly so it works even after the crashed container is gone: + `model logs` (list boots), `model logs ` (tail latest), and + `model logs --previous` (tail the boot that crashed, after a restart). + +### Changed + +- `model init` / `model serve` / `model fleet up` pre-create the host log dir + (user-owned) before compose bind-mounts it, so logs are never root-owned. + +### Fixed + ## [0.22.1] - 2026-06-19 ### Fixed diff --git a/CLAUDE.md b/CLAUDE.md index a69b120..04da325 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -67,13 +67,13 @@ model_gear/ # Python package (pip install model-gear) ├── _runtime_ops.py # shared glue (deployment dir, port, compose_check) └── _commands/ # one module per verb: register(sub) + handler ├── switch.py serve.py stop.py status.py assess.py benchmark.py init.py fleet.py - └── tunnel.py whoami.py learn.py explain.py overview.py doctor.py cli.py + └── logs.py tunnel.py whoami.py learn.py explain.py overview.py doctor.py cli.py ``` **Mutation safety:** write verbs (`switch`, `serve`, `stop`, `init`, `tunnel`) default to **dry-run**; require `--apply` to commit. Agents call CLIs in loops, so safe-by-default is mandatory. The read-only verbs (`status`, `assess`, -`benchmark`, `overview`, `whoami`, `explain`, `doctor`) never change the world. +`benchmark`, `logs`, `overview`, `whoami`, `explain`, `doctor`) never change the world. ## Build / test / publish diff --git a/docs/durable-logs.md b/docs/durable-logs.md new file mode 100644 index 0000000..60ec8a2 --- /dev/null +++ b/docs/durable-logs.md @@ -0,0 +1,97 @@ +# Durable logs: never lose a crash trace again + +When a vLLM container restarts or is recreated, its `docker logs` are gone. That +is exactly how the EngineCore crash trace in +[issue #50](https://github.com/agentculture/model-gear/issues/50) vanished before +anyone could read it: the server 500'd on a tool-calling request, the engine went +down, and by the time the box was looked at, a restart had wiped the logs — so +the root cause could not be investigated for lack of data. + +model-gear fixes the **observability gap**, not (yet) the crash itself: it makes +each vLLM service's output durable so the *next* crash leaves a trace you can +read. Pinning the EngineCore root cause (MTP speculative decoding + tools vs FP4) +needs a controlled repro **with that durable trace in hand** — durable logs is +the prerequisite that unblocks it. + +## How it works + +`model init` scaffolds **`mg-logwrap.sh`** next to `docker-compose.yml`. Each +vLLM service bind-mounts it as the container **entrypoint**, so the real +`command:` (the `vllm serve …` arg list, unchanged) arrives at the wrapper as +`"$@"`. The wrapper: + +1. opens a **per-boot** file `-.log` under the host-mounted log + dir and points `-latest.log` at it; +2. tees `stdout`+`stderr` to that file **and** passes them through to the console + (so `docker logs` keeps working too); +3. `exec`s the real command, so **vLLM stays the signal target** — `docker stop` + still drains it gracefully (SIGTERM reaches vLLM, not a shell), and the + container's exit code is vLLM's (so `restart: unless-stopped` is unaffected). + +Because it tees at the process-I/O level — below Python's logging — it captures +**both** Python tracebacks **and** native `stderr` aborts (CUDA / C++ / OOM), +which is the class of crash that most needs investigating and which Python-level +file logging would miss. If anything about logging fails (no log dir, read-only +mount, no `bash`), the wrapper falls back to a plain `exec "$@"` — logging can +never stop the model from serving. + +### Paths + +| | Host | In container | +|---|---|---| +| Log dir | `${MODEL_GEAR_LOG_DIR:-/logs}` | `/logs/model-gear` | +| Single model | `…/logs/vllm-.log` | `/logs/model-gear/vllm-.log` | +| Fleet gears | `…/logs/{primary,embed,rerank}-.log` | `/logs/model-gear/-.log` | + +The host dir is created (user-owned) by `model init`, `model serve`, and +`model fleet up` before compose bind-mounts it, so the logs are never +root-owned. Per-boot files mean the **crash boot is preserved as its own file** +and never overwritten by the restart that follows it. + +## Reading the logs — `model logs` + +`model logs` is read-only and reads the **host** files directly, so it works even +after the crashed container is gone (`docker logs` would not): + +```text +model logs # list per-boot files (newest first) + the log dir +model logs vllm # tail the latest boot for a service +model logs vllm --previous # tail the boot BEFORE the latest — i.e. the crashed + # boot, after a restart created a fresh healthy one +model logs primary -n 200 # more lines (fleet service) +model logs --json # structured listing +``` + +The `--previous` flag is the #50 investigation path: after a crash+restart, the +latest boot is the healthy one — `--previous` tails the boot that actually +crashed. + +### Pruning + +Per-boot files accumulate across restarts. They are plain files under the host +log dir; prune old ones with a one-liner, e.g. keep the newest 20 per service: + +```bash +ls -1t /logs/vllm-*.log | tail -n +21 | xargs -r rm +``` + +## Why not OTEL? + +OpenTelemetry was considered first. vLLM's OTEL support is **traces-only** +(`--otlp-traces-endpoint`, request spans) — it has **no native OTLP log export**, +and a crash traceback is not a span (the engine dies), so OTEL tracing would not +capture the very thing #50 needs. Capturing logs via OTEL would require an OTEL +Collector + `filelog` receiver sidecar reading the same `stderr` plus a backend +to store it — significant new infrastructure for no gain over a host file. So +crash durability is done at the file level; OTEL **traces** remain a future +opt-in for *request* observability (latency/token spans), a separate concern from +crash logs. + +## Scope + +- Wrapped: the vLLM generate/embed/rerank services (single-model `vllm`, fleet + `primary` / `embed` / `rerank`). +- Not changed: the model's serving flags/behaviour, the `restart:` policy, or the + healthcheck. No docker-socket mounts, no new runtime dependencies. Auto-restart + / autoheal is intentionally **out of scope** here (see #50) — this PR makes the + crash investigable; recovery is a separate decision. diff --git a/docs/gateway-fleet.md b/docs/gateway-fleet.md index 09019b3..582b240 100644 --- a/docs/gateway-fleet.md +++ b/docs/gateway-fleet.md @@ -52,6 +52,11 @@ The backends are reachable only on the compose network (`http://vllm-primary:800 gateway needs no Docker socket access — compose owns the lifecycle; the gateway only routes. +Each vLLM gear runs through `mg-logwrap` so its output (and any crash trace) +persists to per-boot files under the host log dir and **survives restart/recreate** — +read them with `model logs {primary,embed,rerank}` even after a container is gone. +See [docs/durable-logs.md](durable-logs.md) (issue #50). + ### Adding a fallback The gateway adds a second backend **only** when `FALLBACK_URL` or diff --git a/model_gear/cli/__init__.py b/model_gear/cli/__init__.py index 96432c5..7d88a3c 100644 --- a/model_gear/cli/__init__.py +++ b/model_gear/cli/__init__.py @@ -69,6 +69,7 @@ def _build_parser() -> argparse.ArgumentParser: from model_gear.cli._commands import fleet as _fleet_cmd from model_gear.cli._commands import init as _init_cmd from model_gear.cli._commands import learn as _learn_cmd + from model_gear.cli._commands import logs as _logs_cmd from model_gear.cli._commands import overview as _overview_cmd from model_gear.cli._commands import serve as _serve_cmd from model_gear.cli._commands import status as _status_cmd @@ -99,6 +100,7 @@ def _build_parser() -> argparse.ArgumentParser: _benchmark_cmd.register(sub) _init_cmd.register(sub) _fleet_cmd.register(sub) + _logs_cmd.register(sub) _tunnel_cmd.register(sub) # Agent-first / introspection verbs (sibling rubric). diff --git a/model_gear/cli/_commands/fleet.py b/model_gear/cli/_commands/fleet.py index 669a193..ee9d7eb 100644 --- a/model_gear/cli/_commands/fleet.py +++ b/model_gear/cli/_commands/fleet.py @@ -24,7 +24,7 @@ from model_gear import assess from model_gear.cli import _runtime_ops from model_gear.cli._output import emit_diagnostic, emit_result -from model_gear.runtime import _compose, _health +from model_gear.runtime import _compose, _env, _health _UNSET = "(unset)" _JSON_HELP = "Emit structured JSON." @@ -58,6 +58,8 @@ def cmd_fleet_up(args: argparse.Namespace) -> int: emit_result(payload if json_mode else msg, json_mode=json_mode) else: emit_diagnostic(f">> building + starting the fleet in {deploy_dir}") + # Ensure the durable-log dir exists (user-owned) before compose bind-mounts it. + _compose.ensure_log_dir(deploy_dir, _env.read_env(env_path, _compose.LOG_DIR_ENV) or None) _runtime_ops.compose_check( _compose.compose_up_build(deploy_dir), "docker compose up -d --build" ) diff --git a/model_gear/cli/_commands/init.py b/model_gear/cli/_commands/init.py index 4ac8505..339d91c 100644 --- a/model_gear/cli/_commands/init.py +++ b/model_gear/cli/_commands/init.py @@ -55,6 +55,10 @@ def _emit_dry_run(target: Path, fleet: bool, audio: bool, json_mode: bool) -> No def _emit_apply(target: Path, fleet: bool, audio: bool, force: bool, json_mode: bool) -> None: written = _compose.write_scaffold(target, force=force, templates=_templates(fleet, audio)) + # Create the durable-log dir now (as the invoking user) so the compose bind-mount + # source exists before `model serve` / `fleet up` — otherwise Docker makes it + # root-owned. The mg-logwrap entrypoint writes per-boot logs here (issue #50). + _compose.ensure_log_dir(target) if fleet: # Pin the gateway image to the model-gear release that scaffolded this. _env.set_env(target / _compose.ENV_FILE, "MODEL_GEAR_VERSION", __version__) diff --git a/model_gear/cli/_commands/logs.py b/model_gear/cli/_commands/logs.py new file mode 100644 index 0000000..2c3648c --- /dev/null +++ b/model_gear/cli/_commands/logs.py @@ -0,0 +1,199 @@ +"""``model logs`` — read the durable, restart-surviving vLLM logs. + +Read-only. ``mg-logwrap`` (the compose entrypoint) tees each vLLM service's +stdout+stderr to a per-boot file under the host log dir, so a crash trace +survives container restart/recreate — the investigation gap behind issue #50. +This verb lists those files and tails one, reading the **host** files directly so +it works even after the crashed container is gone (``docker logs`` would not). + + model logs # list per-boot log files (newest first) + the dir + model logs vllm # tail the latest log for a service (vllm/primary/embed/rerank) + model logs primary -n 200 # tail more lines + model logs --list --json # structured listing +""" + +from __future__ import annotations + +import argparse +from pathlib import Path + +from model_gear.cli import _runtime_ops +from model_gear.cli._output import emit_result +from model_gear.runtime import _compose, _env + +# Per-boot files are "-.log"; the "-latest.log" symlink +# is a convenience pointer we skip when listing real boots. +_LATEST_SUFFIX = "-latest.log" + + +def collect_logs(log_dir: Path, service: str | None = None) -> list[dict]: + """Per-boot log files under ``log_dir``, newest first (pure; no docker). + + Each entry: ``{name, service, path, size, mtime}``. The ``-latest.log`` + symlinks are skipped (they point at a file already listed). ``service`` filters + by filename prefix (``vllm`` / ``primary`` / ``embed`` / ``rerank``). + """ + if not log_dir.is_dir(): + return [] + out: list[dict] = [] + for p in log_dir.glob("*.log"): + # Skip symlinks (the -latest.log pointer AND any planted symlink): + # never follow a symlink out of the log dir to a file like /etc/shadow — + # mg-logwrap only ever writes regular per-boot files (security, Qodo review). + if p.is_symlink() or p.name.endswith(_LATEST_SUFFIX) or not p.is_file(): + continue + svc = p.name.split("-", 1)[0] + if service and svc != service: + continue + try: + st = p.stat() + except OSError: + continue + out.append( + { + "name": p.name, + "service": svc, + "path": str(p), + "size": st.st_size, + "mtime": st.st_mtime, + } + ) + out.sort(key=lambda e: e["mtime"], reverse=True) + return out + + +def tail_lines(path: Path, n: int, max_bytes: int = 262144) -> str: + """Last ``n`` lines of ``path`` without reading the whole (possibly huge) file. + + vLLM logs every few seconds, so a boot file can be large; read only the final + ``max_bytes`` and return the last ``n`` lines of that window. + """ + # Defense in depth: refuse to read through a symlink even if one reaches here + # (collect_logs already filters them out of the selection). + if path.is_symlink(): + return f"(refusing to read a symlink: {path})" + try: + size = path.stat().st_size + with path.open("rb") as fh: + if size > max_bytes: + fh.seek(size - max_bytes) + data = fh.read() + except OSError as exc: + return f"(could not read {path}: {exc})" + text = data.decode("utf-8", errors="replace") + lines = text.splitlines() + return "\n".join(lines[-n:]) + + +def _resolve_log_dir(args: argparse.Namespace) -> Path: + deploy_dir = _runtime_ops.deployment_dir(args) + env_path = deploy_dir / _compose.ENV_FILE + configured = _env.read_env(env_path, _compose.LOG_DIR_ENV) or None + return _compose.durable_log_dir(deploy_dir, configured) + + +def _human_size(n: int) -> str: + size = float(n) + for unit in ("B", "K", "M", "G"): + if size < 1024 or unit == "G": + return f"{int(size)}{unit}" + size /= 1024 + return f"{int(size)}G" + + +def _emit_tail(args, log_dir: Path, service: str, entries: list[dict], json_mode: bool) -> None: + """Tail mode: show the latest boot for ``service`` (or the crashed one with --previous).""" + if not entries: + msg = f"no logs for '{service}' in {log_dir}" + emit_result( + {"log_dir": str(log_dir), "service": service, "files": []} if json_mode else msg, + json_mode=json_mode, + ) + return + # --previous tails the boot *before* the latest — i.e. the boot that crashed, + # the one to investigate after a restart created a fresh (healthy) boot file. + want_prev = bool(getattr(args, "previous", False)) + idx = 1 if want_prev and len(entries) > 1 else 0 + chosen = entries[idx] + # Flag the case where --previous was asked but there is no earlier boot, so the + # reader isn't misled into thinking the only boot is the crashed one. + only_one = want_prev and len(entries) == 1 + n = int(getattr(args, "lines", 40)) + body = tail_lines(Path(chosen["path"]), n) + if json_mode: + emit_result( + { + "log_dir": str(log_dir), + "service": service, + "file": chosen["path"], + "lines": n, + "only_boot": only_one, + "tail": body, + }, + json_mode=True, + ) + else: + note = " (only 1 boot — showing latest)" if only_one else "" + emit_result(f">> {chosen['path']} (last {n} lines){note}\n{body}", json_mode=False) + + +def _emit_listing(log_dir: Path, entries: list[dict], json_mode: bool) -> None: + """Listing mode (default / --list): per-boot files, newest first, latest flagged.""" + if json_mode: + emit_result({"log_dir": str(log_dir), "files": entries}, json_mode=True) + return + if not entries: + emit_result( + f"no durable logs yet in {log_dir}\n" + ">> they appear once a vLLM service starts (model serve / fleet up).", + json_mode=False, + ) + return + lines = [f"log dir: {log_dir}", "boots (newest first):"] + seen_services: set[str] = set() + for e in entries: + latest = "" if e["service"] in seen_services else " <- latest" + seen_services.add(e["service"]) + lines.append(f" {e['name']:<34} {_human_size(e['size']):>6}{latest}") + lines.append(">> tail one with: model logs (e.g. model logs vllm)") + emit_result("\n".join(lines), json_mode=False) + + +def cmd_logs(args: argparse.Namespace) -> int: + json_mode = bool(getattr(args, "json", False)) + log_dir = _resolve_log_dir(args) + service = getattr(args, "service", None) + entries = collect_logs(log_dir, service) + if service and not getattr(args, "list", False): + _emit_tail(args, log_dir, service, entries, json_mode) + else: + _emit_listing(log_dir, entries, json_mode) + return 0 + + +def register(sub: argparse._SubParsersAction) -> None: + p = sub.add_parser( + "logs", + help="Read-only: list/tail the durable vLLM logs that survive restart " + "(model logs [service]; issue #50).", + ) + p.add_argument( + "service", + nargs="?", + help="Service to tail (vllm / primary / embed / rerank). Omit to list all boots.", + ) + p.add_argument("-n", "--lines", type=int, default=40, help="Lines to tail (default 40).") + p.add_argument( + "-p", + "--previous", + action="store_true", + help="Tail the boot before the latest — the crashed boot to investigate after a restart.", + ) + p.add_argument( + "--list", action="store_true", help="List boot files even when a service is given." + ) + p.add_argument( + "--compose-dir", help="Deployment dir (default: $MODEL_GEAR_DIR or ~/.model-gear)." + ) + p.add_argument("--json", action="store_true", help="Emit structured JSON.") + p.set_defaults(func=cmd_logs) diff --git a/model_gear/cli/_commands/overview.py b/model_gear/cli/_commands/overview.py index f3bc220..2a06b91 100644 --- a/model_gear/cli/_commands/overview.py +++ b/model_gear/cli/_commands/overview.py @@ -29,6 +29,7 @@ "tunnel — expose the local API at a public hostname via a Cloudflare Tunnel " "(--stop; dry-run; --apply)", "status — current model, container state, /health", + "logs — read-only: list/tail the durable vLLM logs that survive restart (issue #50)", "assess — correctness probes against the served model", "benchmark — decode throughput + prefill latency", "overview — this snapshot (--current / --list to filter)", diff --git a/model_gear/cli/_commands/serve.py b/model_gear/cli/_commands/serve.py index 170f230..511d56c 100644 --- a/model_gear/cli/_commands/serve.py +++ b/model_gear/cli/_commands/serve.py @@ -34,6 +34,8 @@ def cmd_serve(args: argparse.Namespace) -> int: ) else: emit_diagnostic(f">> starting the vLLM server in {deploy_dir}") + # Ensure the durable-log dir exists (user-owned) before compose bind-mounts it. + _compose.ensure_log_dir(deploy_dir, _env.read_env(env_path, _compose.LOG_DIR_ENV) or None) _runtime_ops.compose_check(_compose.compose_up_detached(deploy_dir), "docker compose up -d") _health.wait_health(port) result = {"serving": True, "port": port, "deployment_dir": str(deploy_dir)} diff --git a/model_gear/runtime/_compose.py b/model_gear/runtime/_compose.py index e8cfe39..5d56da3 100644 --- a/model_gear/runtime/_compose.py +++ b/model_gear/runtime/_compose.py @@ -20,6 +20,15 @@ ENV_FILE = ".env" DOCKERFILE_GATEWAY = "Dockerfile.gateway" +# Durable logs (issue #50). `mg-logwrap.sh` is scaffolded next to docker-compose.yml +# and bind-mounted into each vLLM service as the entrypoint; it tees stdout+stderr to +# a per-boot file under the host log dir so a crash trace survives restart/recreate. +# Host dir: $MODEL_GEAR_LOG_DIR (in .env) or /logs (matches the compose default +# `${MODEL_GEAR_LOG_DIR:-./logs}`); in-container it mounts at /logs/model-gear. +LOG_WRAPPER = "mg-logwrap.sh" +LOG_DIRNAME = "logs" +LOG_DIR_ENV = "MODEL_GEAR_LOG_DIR" + # Fleet container names (model init --fleet / model fleet ...): the always-warm # Qwen generate primary, the co-resident embedding + reranker gears, and the # stdlib gateway that fronts them on one OpenAI port. All four are in the default @@ -50,12 +59,14 @@ SINGLE_TEMPLATES = { "docker-compose.yml": COMPOSE_FILE, "env.example": ENV_FILE, + LOG_WRAPPER: LOG_WRAPPER, CF_TUNNEL_EXAMPLE: CF_TUNNEL_EXAMPLE, } FLEET_TEMPLATES = { "fleet/docker-compose.yml": COMPOSE_FILE, "fleet/env.example": ENV_FILE, "fleet/Dockerfile.gateway": DOCKERFILE_GATEWAY, + LOG_WRAPPER: LOG_WRAPPER, CF_TUNNEL_EXAMPLE: CF_TUNNEL_EXAMPLE, } # The --audio extras layered on FLEET_TEMPLATES: the compose override, the two @@ -82,6 +93,37 @@ def default_deployment_dir() -> Path: return Path.home() / ".model-gear" +def durable_log_dir(deploy_dir: os.PathLike | str, configured: str | None = None) -> Path: + """Host directory holding the per-boot vLLM logs that ``mg-logwrap`` writes. + + Mirrors the compose default ``${MODEL_GEAR_LOG_DIR:-./logs}``: an absolute + ``configured`` path (``MODEL_GEAR_LOG_DIR`` from ``.env``) wins; a relative one + resolves against the deployment dir; unset falls back to ``/logs``. So + the CLI reads logs from exactly where compose mounts them. + """ + base = Path(deploy_dir).expanduser() + if configured: + p = Path(configured).expanduser() + return p if p.is_absolute() else (base / p) + return base / LOG_DIRNAME + + +def ensure_log_dir(deploy_dir: os.PathLike | str, configured: str | None = None) -> Path: + """Create the durable-log dir before ``docker compose up``. + + The compose bind-mounts this host dir into each vLLM container; if it doesn't + exist when compose runs, Docker creates it **root-owned**. Creating it here (as + the invoking user) keeps the logs user-readable. Best-effort — returns the dir + even if mkdir fails (the wrapper falls back to plain exec, never blocking serve). + """ + d = durable_log_dir(deploy_dir, configured) + try: + d.mkdir(parents=True, exist_ok=True) + except OSError: + pass + return d + + def resolve_deployment_dir(explicit: os.PathLike | str | None) -> Path: """Resolve the directory holding ``docker-compose.yml``. diff --git a/model_gear/templates/docker-compose.yml b/model_gear/templates/docker-compose.yml index c478afe..f6cbfac 100644 --- a/model_gear/templates/docker-compose.yml +++ b/model_gear/templates/docker-compose.yml @@ -49,13 +49,27 @@ services: # `Authorization: Bearer $CULTURE_VLLM_API_KEY`. REQUIRED before exposing the # API publicly (e.g. `model tunnel`). See env.example + README "Expose the API". - VLLM_API_KEY=${CULTURE_VLLM_API_KEY:-} + # mg-logwrap writes per-boot logs to $MG_LOG_DIR/$MG_LOG_NAME-.log. + # MG_LOG_DIR is the in-container mount point (set explicitly so it can't drift + # from the volume below); MG_LOG_NAME namespaces this service's file. + - MG_LOG_DIR=/logs/model-gear + - MG_LOG_NAME=vllm volumes: # Persist downloaded weights across restarts. HF_CACHE overrides the host # path; otherwise ~/.cache/huggingface, with /root as the fallback if HOME # is unset (so the mount never collapses to /.cache/huggingface). - ${HF_CACHE:-${HOME:-/root}/.cache/huggingface}:/root/.cache/huggingface + # Durable logs: tee stdout+stderr to a host file that survives restart/recreate, + # so an EngineCore crash trace is never lost again (issue #50). MODEL_GEAR_LOG_DIR + # overrides the host dir; default ./logs next to this compose file. Read it with + # `model logs` (or straight from the host dir), even after the container is gone. + - ${MODEL_GEAR_LOG_DIR:-./logs}:/logs/model-gear + - ./mg-logwrap.sh:/usr/local/bin/mg-logwrap:ro ports: - "${VLLM_PORT:-8000}:8000" + # mg-logwrap tees this service's output to /logs/model-gear, then `exec`s the + # command below so vLLM stays the signal target (graceful SIGTERM). See mg-logwrap.sh. + entrypoint: ["bash", "/usr/local/bin/mg-logwrap"] command: - vllm - serve diff --git a/model_gear/templates/env.example b/model_gear/templates/env.example index 7122f70..f184279 100644 --- a/model_gear/templates/env.example +++ b/model_gear/templates/env.example @@ -97,3 +97,9 @@ VLLM_QUANTIZATION=modelopt # (or /root/.cache/huggingface if $HOME is unset). Set to reuse an existing cache # or to pin a specific disk. HF_CACHE= + +# Host dir for durable, restart-surviving logs (issue #50). The vLLM service tees +# its stdout+stderr here as per-boot files (vllm-.log) via mg-logwrap, so a +# crash trace survives container restart/recreate. Read them with `model logs`. +# Default ./logs next to docker-compose.yml; set an absolute path to pin a disk. +MODEL_GEAR_LOG_DIR= diff --git a/model_gear/templates/fleet/docker-compose.yml b/model_gear/templates/fleet/docker-compose.yml index dfc425b..e26307a 100644 --- a/model_gear/templates/fleet/docker-compose.yml +++ b/model_gear/templates/fleet/docker-compose.yml @@ -38,11 +38,19 @@ services: environment: - HF_HOME=/root/.cache/huggingface - TOKENIZERS_PARALLELISM=false + - MG_LOG_DIR=/logs/model-gear # in-container mount point (explicit, no drift) + - MG_LOG_NAME=primary # → /logs/model-gear/primary-.log volumes: - ${HF_CACHE:-${HOME:-/root}/.cache/huggingface}:/root/.cache/huggingface + # Durable logs that survive restart/recreate (issue #50) — see mg-logwrap.sh. + - ${MODEL_GEAR_LOG_DIR:-./logs}:/logs/model-gear + - ./mg-logwrap.sh:/usr/local/bin/mg-logwrap:ro # No host port — reachable only as http://vllm-primary:8000 on the compose net. expose: - "8000" + # mg-logwrap tees output to /logs/model-gear, then `exec`s the command (vLLM stays + # the signal target). The command list below is unchanged. + entrypoint: ["bash", "/usr/local/bin/mg-logwrap"] command: - vllm - serve @@ -116,10 +124,16 @@ services: environment: - HF_HOME=/root/.cache/huggingface - TOKENIZERS_PARALLELISM=false + - MG_LOG_DIR=/logs/model-gear # in-container mount point (explicit, no drift) + - MG_LOG_NAME=embed # → /logs/model-gear/embed-.log volumes: - ${HF_CACHE:-${HOME:-/root}/.cache/huggingface}:/root/.cache/huggingface + # Durable logs that survive restart/recreate (issue #50) — see mg-logwrap.sh. + - ${MODEL_GEAR_LOG_DIR:-./logs}:/logs/model-gear + - ./mg-logwrap.sh:/usr/local/bin/mg-logwrap:ro expose: - "8000" + entrypoint: ["bash", "/usr/local/bin/mg-logwrap"] command: - vllm - serve @@ -163,10 +177,16 @@ services: environment: - HF_HOME=/root/.cache/huggingface - TOKENIZERS_PARALLELISM=false + - MG_LOG_DIR=/logs/model-gear # in-container mount point (explicit, no drift) + - MG_LOG_NAME=rerank # → /logs/model-gear/rerank-.log volumes: - ${HF_CACHE:-${HOME:-/root}/.cache/huggingface}:/root/.cache/huggingface + # Durable logs that survive restart/recreate (issue #50) — see mg-logwrap.sh. + - ${MODEL_GEAR_LOG_DIR:-./logs}:/logs/model-gear + - ./mg-logwrap.sh:/usr/local/bin/mg-logwrap:ro expose: - "8000" + entrypoint: ["bash", "/usr/local/bin/mg-logwrap"] command: - vllm - serve diff --git a/model_gear/templates/fleet/env.example b/model_gear/templates/fleet/env.example index 582ee7c..172d747 100644 --- a/model_gear/templates/fleet/env.example +++ b/model_gear/templates/fleet/env.example @@ -26,6 +26,12 @@ HF_TOKEN= # to ~/.cache/huggingface (or /root/.cache/huggingface if $HOME is unset). HF_CACHE= +# Host dir for durable, restart-surviving logs (issue #50). Each vLLM gear tees its +# stdout+stderr here as per-boot files ({primary,embed,rerank}-.log) via +# mg-logwrap, so a crash trace survives restart/recreate. Read with `model logs`. +# Default ./logs next to docker-compose.yml; set an absolute path to pin a disk. +MODEL_GEAR_LOG_DIR= + # --- Primary backend (the gateway's default model) ------------------------ # The MTP speculative-decoding 27B (text-only): ~2.4x decode vs the archived # baseline, tool calling + reasoning verified 2026-05-31. The MTP serve flags diff --git a/model_gear/templates/mg-logwrap.sh b/model_gear/templates/mg-logwrap.sh new file mode 100644 index 0000000..95ac50f --- /dev/null +++ b/model_gear/templates/mg-logwrap.sh @@ -0,0 +1,46 @@ +#!/usr/bin/env bash +# model-gear log wrapper — make the server's output (and its crash trace) durable. +# +# `model init` materialises this next to docker-compose.yml; each vLLM service +# bind-mounts it at /usr/local/bin/mg-logwrap and runs it as the entrypoint, so +# the real `command:` (the vllm arg list) arrives here verbatim as "$@". +# +# Why this exists: when a vLLM container is restarted or recreated (docker +# restart, `docker compose up` after `model switch`, a `compose down/up`, …) its +# `docker logs` are gone — which is exactly how the EngineCore crash trace in +# issue #50 vanished before anyone could read it. This wrapper tees stdout+stderr +# to a per-boot file under a host-mounted log dir, so the trace survives any +# restart or recreate. +# +# It tees at the process-I/O level (not through Python logging), so it captures +# BOTH Python tracebacks AND native stderr aborts (CUDA / C++ / OOM) — the latter +# bypass Python logging entirely and are the crashes that most need investigating. +# The final `exec` makes the real server the signal target, so `docker stop` still +# drains it cleanly (graceful SIGTERM). If anything about logging fails (no log +# dir, read-only mount, no bash process substitution, …) it falls back to a plain +# exec — logging can never stop the model from serving. +set -u + +name="${MG_LOG_NAME:-server}" +dir="${MG_LOG_DIR:-/logs/model-gear}" +ts="$(date -u +%Y%m%dT%H%M%SZ 2>/dev/null || echo boot)" +log="${dir}/${name}-${ts}.log" + +# Per-boot file (the crash boot is preserved as its own file, never overwritten by +# the restart) plus a stable -latest.log pointer for quick tailing and +# `model logs`. The `:` no-op probes that the file is actually writable before we +# commit to teeing into it. +if mkdir -p "$dir" 2>/dev/null && : 2>/dev/null >>"$log"; then + ln -sf "${name}-${ts}.log" "${dir}/${name}-latest.log" 2>/dev/null || true + printf '=== model-gear %s :: boot %s :: %s ===\n' "$name" "$ts" "$*" >>"$log" + # exec with redirections only (no command): this does NOT replace the shell — it + # rewires THIS shell's fd1+fd2 to a tee that writes the durable file *and* passes + # output through to the original stdout, so `docker logs` keeps working too. The + # tee child gets EOF when the server exits and flushes its buffer. + exec > >(tee -a "$log") 2>&1 +fi + +# exec the real command: this DOES replace the shell, so the server (not bash) is +# the container's main process — it receives SIGTERM directly (graceful shutdown) +# and its exit code becomes the container's (so `restart:` behaves as before). +exec "$@" diff --git a/pyproject.toml b/pyproject.toml index 1904fcb..70b0618 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "model-gear" -version = "0.22.1" +version = "0.23.0" description = "model-gear — run, assess, and switch the local vLLM model." readme = "README.md" license = "MIT" diff --git a/tests/test_cli_logs.py b/tests/test_cli_logs.py new file mode 100644 index 0000000..d68167d --- /dev/null +++ b/tests/test_cli_logs.py @@ -0,0 +1,196 @@ +"""Tests for ``model logs`` + the durable-log helpers (issue #50). + +Pure file I/O — no docker. A deployment is scaffolded into a tmp dir (so +``resolve_deployment_dir`` finds a compose file) and fake per-boot log files are +written with controlled mtimes to assert newest-first ordering and crash-boot +recovery via ``--previous``. +""" + +from __future__ import annotations + +import json +import os +from pathlib import Path + +from model_gear.cli import main +from model_gear.cli._commands import logs as logs_cmd +from model_gear.runtime import _compose + +# --- log dir resolution ---------------------------------------------------- + + +def test_durable_log_dir_default(tmp_path) -> None: + # Unset → /logs (matches the compose default ${MODEL_GEAR_LOG_DIR:-./logs}). + assert _compose.durable_log_dir(tmp_path) == tmp_path / "logs" + + +def test_durable_log_dir_relative_resolves_against_deploy(tmp_path) -> None: + assert _compose.durable_log_dir(tmp_path, "mylogs") == tmp_path / "mylogs" + + +def test_durable_log_dir_absolute_wins(tmp_path) -> None: + abs_dir = tmp_path / "elsewhere" + assert _compose.durable_log_dir(tmp_path, str(abs_dir)) == abs_dir + + +def test_ensure_log_dir_creates(tmp_path) -> None: + d = _compose.ensure_log_dir(tmp_path) + assert d.is_dir() and d == tmp_path / "logs" + + +# --- collect_logs / tail_lines (pure) -------------------------------------- + + +def _boot(log_dir: Path, name: str, mtime: float, body: str = "x") -> Path: + log_dir.mkdir(parents=True, exist_ok=True) + p = log_dir / name + p.write_text(body, encoding="utf-8") + os.utime(p, (mtime, mtime)) + return p + + +def test_collect_logs_newest_first_and_skips_latest_symlink(tmp_path) -> None: + d = tmp_path / "logs" + _boot(d, "vllm-20260620T060000Z.log", 1000.0) + newest = _boot(d, "vllm-20260620T070000Z.log", 2000.0) + # a -latest.log pointer must be skipped (it duplicates a real boot) + _boot(d, "vllm-latest.log", 2000.0) + got = logs_cmd.collect_logs(d) + names = [e["name"] for e in got] + assert names == [newest.name, "vllm-20260620T060000Z.log"] + assert "vllm-latest.log" not in names + + +def test_collect_logs_skips_symlinks(tmp_path) -> None: + # Security: a planted symlink named like a boot log must not be followed/listed. + d = tmp_path / "logs" + real = _boot(d, "vllm-20260620T060000Z.log", 1000.0) + (d / "vllm-evil.log").symlink_to(real) # could point anywhere (e.g. /etc/shadow) + names = [e["name"] for e in logs_cmd.collect_logs(d)] + assert names == ["vllm-20260620T060000Z.log"] + assert "vllm-evil.log" not in names + + +def test_tail_lines_refuses_symlink(tmp_path) -> None: + real = tmp_path / "real.log" + real.write_text("secret", encoding="utf-8") + link = tmp_path / "link.log" + link.symlink_to(real) + assert "refusing to read a symlink" in logs_cmd.tail_lines(link, 10) + + +def test_collect_logs_filters_by_service(tmp_path) -> None: + d = tmp_path / "logs" + _boot(d, "vllm-20260620T060000Z.log", 1000.0) + _boot(d, "embed-20260620T060000Z.log", 1001.0) + assert [e["service"] for e in logs_cmd.collect_logs(d, "embed")] == ["embed"] + + +def test_collect_logs_missing_dir_is_empty(tmp_path) -> None: + assert logs_cmd.collect_logs(tmp_path / "nope") == [] + + +def test_tail_lines_returns_last_n(tmp_path) -> None: + p = tmp_path / "a.log" + p.write_text("\n".join(f"line{i}" for i in range(100)), encoding="utf-8") + assert logs_cmd.tail_lines(p, 3) == "line97\nline98\nline99" + + +def test_tail_lines_window_on_large_file(tmp_path) -> None: + p = tmp_path / "big.log" + p.write_text("HEAD\n" + ("z" * 500000) + "\nTAILMARK", encoding="utf-8") + out = logs_cmd.tail_lines(p, 1, max_bytes=1024) + assert out == "TAILMARK" # only the final window is read + + +# --- the CLI verb ---------------------------------------------------------- + + +def _deploy_with_logs(tmp_path, capsys) -> Path: + target = tmp_path / "deploy" + assert main(["init", str(target), "--apply"]) == 0 + d = target / "logs" + _boot(d, "vllm-20260620T060000Z.log", 1000.0, body="OLD crash\nTraceback: EngineCore boom") + _boot(d, "vllm-20260620T070000Z.log", 2000.0, body="NEW healthy boot") + capsys.readouterr() # drop init's stdout so the asserted command's output is clean + return target + + +def test_logs_list_text(tmp_path, capsys) -> None: + target = _deploy_with_logs(tmp_path, capsys) + assert main(["logs", "--compose-dir", str(target)]) == 0 + out = capsys.readouterr().out + assert "vllm-20260620T070000Z.log" in out + assert "<- latest" in out # newest boot flagged + + +def test_logs_list_json(tmp_path, capsys) -> None: + target = _deploy_with_logs(tmp_path, capsys) + assert main(["logs", "--compose-dir", str(target), "--json"]) == 0 + payload = json.loads(capsys.readouterr().out) + # newest first + assert payload["files"][0]["name"] == "vllm-20260620T070000Z.log" + + +def test_logs_tail_latest(tmp_path, capsys) -> None: + target = _deploy_with_logs(tmp_path, capsys) + assert main(["logs", "vllm", "--compose-dir", str(target)]) == 0 + assert "NEW healthy boot" in capsys.readouterr().out + + +def test_logs_previous_shows_crash_boot(tmp_path, capsys) -> None: + # The whole point of #50: after a restart, --previous tails the boot that crashed. + target = _deploy_with_logs(tmp_path, capsys) + assert main(["logs", "vllm", "--previous", "--compose-dir", str(target)]) == 0 + out = capsys.readouterr().out + assert "EngineCore boom" in out + + +def test_logs_previous_single_boot_notes(tmp_path, capsys) -> None: + # --previous with no earlier boot shows the latest, but says so (review feedback). + target = tmp_path / "deploy" + assert main(["init", str(target), "--apply"]) == 0 + _boot(target / "logs", "vllm-20260620T060000Z.log", 1000.0, body="only boot") + capsys.readouterr() + assert main(["logs", "vllm", "--previous", "--compose-dir", str(target)]) == 0 + assert "only 1 boot" in capsys.readouterr().out + + +def test_logs_empty_dir_friendly(tmp_path, capsys) -> None: + target = tmp_path / "deploy" + assert main(["init", str(target), "--apply"]) == 0 + assert main(["logs", "--compose-dir", str(target)]) == 0 + assert "no durable logs yet" in capsys.readouterr().out + + +def test_logs_unknown_service_no_crash(tmp_path, capsys) -> None: + target = _deploy_with_logs(tmp_path, capsys) + assert main(["logs", "nosuchsvc", "--compose-dir", str(target)]) == 0 + assert "no logs for 'nosuchsvc'" in capsys.readouterr().out + + +# --- the shipped wrapper --------------------------------------------------- + + +def test_logwrap_template_shipped_and_safe() -> None: + from importlib.resources import files + + content = (files("model_gear.templates") / _compose.LOG_WRAPPER).read_text() + # Always execs the real command (so logging can never block serving) ... + assert 'exec "$@"' in content + # ... tees to a durable file, and is parameterised per service. + assert "tee -a" in content + assert "MG_LOG_NAME" in content and "MG_LOG_DIR" in content + # In both template sets (single + fleet). + assert "mg-logwrap.sh" in _compose.SINGLE_TEMPLATES + assert "mg-logwrap.sh" in _compose.FLEET_TEMPLATES + + +def test_compose_log_dir_does_not_drift_from_python() -> None: + # Guard: the compose host-dir default and the in-container path must stay in sync + # with the Python helpers that read them (review feedback). + from importlib.resources import files + + compose = (files("model_gear.templates") / "docker-compose.yml").read_text() + assert f"${{MODEL_GEAR_LOG_DIR:-./{_compose.LOG_DIRNAME}}}:/logs/model-gear" in compose + assert "MG_LOG_DIR=/logs/model-gear" in compose diff --git a/tests/test_init.py b/tests/test_init.py index 151bb76..23a31e1 100644 --- a/tests/test_init.py +++ b/tests/test_init.py @@ -32,6 +32,14 @@ def test_init_apply_writes_both_files(tmp_path, capsys) -> None: assert "--enable-auto-tool-choice" in compose assert "--tool-call-parser=${VLLM_TOOL_CALL_PARSER:-qwen3_coder}" in compose assert "VLLM_TOOL_CALL_PARSER=qwen3_coder" in (target / ".env").read_text() + # Durable logs (issue #50): the wrapper is scaffolded, the log dir is pre-created + # (user-owned), and the vllm service runs the wrapper as its entrypoint + tees to + # a host-mounted log dir. + assert (target / "mg-logwrap.sh").is_file() + assert (target / "logs").is_dir() + assert 'entrypoint: ["bash", "/usr/local/bin/mg-logwrap"]' in compose + assert "MG_LOG_NAME=vllm" in compose + assert "/logs/model-gear" in compose def test_init_apply_json(tmp_path, capsys) -> None: @@ -40,7 +48,12 @@ def test_init_apply_json(tmp_path, capsys) -> None: assert rc == 0 payload = json.loads(capsys.readouterr().out) assert payload["scaffolded"] == str(target) - assert set(payload["files"]) == {"docker-compose.yml", ".env", "cf-tunnel.env.example"} + assert set(payload["files"]) == { + "docker-compose.yml", + ".env", + "mg-logwrap.sh", + "cf-tunnel.env.example", + } def test_init_refuses_overwrite_without_force(tmp_path) -> None: @@ -98,6 +111,13 @@ def test_init_fleet_apply_writes_three_files(tmp_path) -> None: # may mention vllm-fallback in "how to add one" comments, so check the # service's container_name, which only appears when the service is defined). assert "model-gear-vllm-fallback" not in compose + # Durable logs (issue #50): wrapper scaffolded + each vLLM gear runs it + names + # its own per-boot log file (primary/embed/rerank). + assert (target / "mg-logwrap.sh").is_file() + assert (target / "logs").is_dir() + assert 'entrypoint: ["bash", "/usr/local/bin/mg-logwrap"]' in compose + for svc in ("primary", "embed", "rerank"): + assert f"MG_LOG_NAME={svc}" in compose env = (target / ".env").read_text() assert "PRIMARY_MODEL=sakamakismile/Qwen3.6-27B-Text-NVFP4-MTP" in env assert "FALLBACK_MODEL=" not in env @@ -117,7 +137,13 @@ def test_init_fleet_dry_run_json(tmp_path, capsys) -> None: payload = json.loads(capsys.readouterr().out) assert payload["fleet"] is True names = {f["name"] for f in payload["files"]} - assert names == {"docker-compose.yml", ".env", "Dockerfile.gateway", "cf-tunnel.env.example"} + assert names == { + "docker-compose.yml", + ".env", + "Dockerfile.gateway", + "mg-logwrap.sh", + "cf-tunnel.env.example", + } assert not target.exists()