Phase 1 — Evidence: logging & failure diagnostics #272

Activity

1. thcp

   added

   observabilityLogging, monitoring, diagnosabilityLogging, monitoring, diagnosability

   on Jul 16, 2026
2. thcp commented on Jul 16, 2026

   

   thcp

   on Jul 16, 2026

   CollaboratorAuthor

   More actions

   Implementation plan — Phase 1: Evidence

   Design decisions are made; this is execution-ready. Findings covered: #291, #278, #277, #280, #292, #283, #293, #294. Split into 5 PRs, each independently shippable, ordered so later PRs build on earlier infra.

   Repo gates for every PR: ruff check AND ruff format --check, pytest (with bundled ffmpeg from data/ffmpeg on PATH for the ffmpeg-gated tests). PR-B additionally needs cargo clippy via WSL (PR CI does not build the Rust desktop app).

   ---

   PR-1A — Rotating file logs + level control + stage-leak fix (#291, #292, #283)

   New module app/core/logging_setup.py:

   def configure_logging() -> None:
       """Attach a RotatingFileHandler to the 'stemdeck' logger. Best-effort:
       a read-only FS (Docker) must never prevent startup."""

   • RotatingFileHandler(LOGS_DIR / "stemdeck.log", maxBytes=5*1024*1024, backupCount=3, encoding="utf-8", delay=True) — delay=True so no file is touched until the first record (read-only FS friendly).
   • Formatter: "%(asctime)s %(levelname).1s %(name)s %(message)s" with ISO datefmt.
   • Level: STEMDECK_LOG_LEVEL env (accepts DEBUG|INFO|WARNING), default INFO; STEMDECK_DEBUG=1 is shorthand for DEBUG.
   • LOGS_DIR.mkdir(parents=True, exist_ok=True) inside a try/except OSError — on failure log a one-line warning to stderr and continue with stdout-only logging. Today ensure_runtime_dirs() only creates LOGS_DIR in portable mode (config.py:123); do NOT change that — create it here instead so server/source runs get it too.
   • Handler attaches to logging.getLogger("stemdeck") only (propagate stays on, so stdout via uvicorn continues unchanged). Guard against double-attach (check existing handlers by a sentinel attribute) — uvicorn --reload re-imports.

   app/main.py: replace the bare logging.getLogger("stemdeck").setLevel(logging.INFO) at main.py:52 with configure_logging(). Fix the stale comment: the "chroma / key candidates" diagnostics are logger.debug and never showed at INFO — now they appear under STEMDECK_LOG_LEVEL=DEBUG (#292; keep them at debug level, don't promote).

   app/pipeline/analyze.py:330 (#283): _set(job, stage=f"Analysis skipped ({e})") → _set(job, stage="Analysis skipped"). The exception is already logger.exception'd one line above; internal reprs must not reach the UI.

   Tests (tests/test_logging_setup.py): file created on first log record; rotation config honored (set maxBytes tiny, log 3 records, assert .1 exists); STEMDECK_LOG_LEVEL=DEBUG makes stemdeck.analyze debug records emit; unwritable LOGS_DIR (monkeypatch to a file path) does not raise. Existing test for analyze stage message updated if any.

   ---

   PR-1B — Desktop: stop truncating backend.log (#278) [Rust]

   desktop/src-tauri/src/main.rs — prepare_backend_stdio() (line 1071): replace the truncating fs::File::create(log_path) with generation rotation before open:

   fn rotate_log(log_path: &Path, keep: usize) { // backend.log -> .1 -> .2, oldest dropped
       for i in (1..keep).rev() {
           let _ = fs::rename(log_path.with_extension(format!("log.{i}")),
                              log_path.with_extension(format!("log.{}", i + 1)));
       }
       let _ = fs::rename(log_path, log_path.with_extension("log.1"));
   }

   Call rotate_log(log_path, 3) then open with create(true).append(true) exactly as today. All renames best-effort (let _ =) — a locked file on Windows must not block launch; worst case we append to the old file, which is still better than truncating it.

   Validation: cargo clippy + cargo build via WSL; manual: launch app twice, confirm backend.log.1 holds the prior session.

   ---

   PR-1C — Failed-job quarantine + error classifier (#277, #294)

   New module app/pipeline/errors.py:

   class SeparationError(RuntimeError):
       def __init__(self, msg, *, tail: list[str], device: str): ...
   
   CAUSES = ("out-of-memory", "unsupported-device", "disk-full", "bad-input", "unknown")
   def classify_failure(text: str) -> str: ...

   Pattern table (case-insensitive substring, first match wins): "cuda out of memory"|"mps backend out of memory"|"not enough memory"|"cannot allocate" → out-of-memory; "no kernel image"|"invalid device"|"mps"+"not supported"|"cudnn" → unsupported-device; "no space left on device"|"errno 28" → disk-full; "invalid data"|"unable to open"|"no stems produced" → bad-input; else unknown. Table-driven so Phase 2's fallback reuses it.

   app/pipeline/separate.py: raise SeparationError(f"demucs failed: {last}", tail=tail[-40:], device=device) instead of bare RuntimeError (separate.py:127). Also _set(job, ...) a new field job.compute_device = device at start (see PR-1E field additions).

   app/pipeline/runner.py — _run_async error branch (line 208–214): replace _rmtree(job_dir) with _quarantine_failed_job(job, job_dir, exc):

   1. Write job_dir/error.txt: timestamp, job id/title, status stage, job.compute_device, DEMUCS_MODEL, exception repr, classified cause, SeparationError.tail if present, stage timings (PR-1E), app version.
   2. Delete heavy payloads inside the dir: source.*, stems/*.wav, video.mp4, the demucs intermediate dir — quarantine must stay KB-scale.
   3. shutil.move(job_dir, JOBS_DIR / "failed" / job.id) (create parent; on collision suffix -2). All steps best-effort with logger.warning on failure, falling back to plain _rmtree so disk never leaks on a pathological error.

   Safety check (verified): registry.restore() and sweep_old_jobs() iterate jobs_dir children filtered by JOB_ID_RE / dir checks — the failed/ dir name doesn't match ^[a-f0-9]{12}$, so it's inert to both. Still add an explicit test.

   Failed-quarantine TTL: new FAILED_TTL_SECONDS = 7*24*3600 in config (env-overridable). In app/main.py:_sweep_loop, the job-TTL sweep stays gated by _sweep_disabled(), but a new sweep_failed_jobs(JOBS_DIR) (in collect.py) runs unconditionally — desktop keeps its persistent library while failed quarantines still expire.

   Job.error_detail: str | None (#294): set to the classified cause + last stderr line (e.g. "out-of-memory — MPS backend out of memory (…)"). Add to to_state(). UI: in the studio/mobile error rendering, show error as today and error_detail as a smaller secondary line when present (find the render site via job.error usage in static/js/job.js / mobile app.js). No disclosure widget — one muted line, error-reporting not feature work.

   Tests: classifier table; quarantine produces error.txt with expected keys and strips WAVs; failed dir ignored by restore/sweep; sweep_failed_jobs TTL; error_detail present in /api/jobs/{id} for a failed job (reuse test_pipeline_runner.py's fake-stage pattern at line 138).

   ---

   PR-1D — Mixdown ffmpeg stderr logging (#280)

   app/api/stems.py — _stream_ffmpeg(cmd) → _stream_ffmpeg(cmd, context: str):

   • stderr=asyncio.subprocess.PIPE; spawn asyncio.create_task(_drain(proc.stderr)) that accumulates the last ~4 KB (deque of lines) — draining is mandatory to avoid pipe-full deadlock.
   • In finally, after proc.wait(): if returncode not in (0, None-killed-by-us) log logger.warning("mixdown ffmpeg exit %s [%s]: %s", rc, context, tail). Distinguish client-disconnect kills (we called proc.kill()) from genuine failures via a local flag.
   • Callers pass context=f"job={job_id} ext={ext} stems={stems}" (both get_mixdown and the zip/video paths that share it, if any).

   Tests: monkeypatch ffmpeg_executable to a script that writes to stderr and exits 2 → response completes, caplog contains the tail; happy path logs nothing.

   ---

   PR-1E — Per-stage timing telemetry (#293)

   app/core/models.py: add stage_timings: dict[str, float] | None = None and compute_device: str | None = None. Include both in to_record()/metadata.json (they're in _JOB_FIELDS automatically) and in to_state().

   app/pipeline/runner.py: tiny helper in _run_common/_run_blocking:

   t = {}; mark = time.monotonic()
   def lap(name): nonlocal mark; t[name] = round(time.monotonic() - mark, 1); mark = time.monotonic()

   Laps: download (in _run_blocking around download()), analyze, separate, post (collect+presence+mix+peaks). On success set job.stage_timings = t and emit ONE summary line:
   logger.info("[%s] done device=%s model=%s %s total=%.1fs", job.id, job.compute_device, DEMUCS_MODEL, " ".join(f"{k}={v}s" for k,v in t.items()), sum(t.values()))
   On failure, pass the partial t into _quarantine_failed_job for error.txt (PR-1C lands first).

   _write_metadata: add stage_timings + compute_device keys; registry._recover_done_job picks them up via meta.get(...) additions.

   Tests: extend the existing runner pipeline test to assert stage_timings keys exist and the summary line is logged.

   ---

   Sequencing & estimates

   1A (0.5d) → 1C (1d, uses 1A's level control) → 1E (0.5d, feeds error.txt) → 1D (0.5d) → 1B (0.5d, independent, needs WSL toolchain).
   Manual end-to-end check after 1C+1E: force a failure (STEMDECK_DEMUCS_MODEL=bogus), confirm jobs/failed/<id>/error.txt tells the whole story, then delete it via the sweep.
3. thcp commented on Jul 17, 2026

   

   thcp

   on Jul 17, 2026

   CollaboratorAuthor

   More actions

   All 8 findings shipped and merged to main:

   PR	Closes	Commit
   #295	#291, #292, #283	995e402
   #296	#277, #294, #293	378c64f
   #297	#280	a666b39
   #298	#278	60959e7

   Phase 1 (Evidence) is complete. Closing.
4. thcp

   closed this as completedon Jul 17, 2026
5. thcp

   self-assigned this

   on Oct 1, 2026