Worker and web processes are silent: no log file, nothing on stdout #11

New issue

Closed

opened 2026-10-15 06:46:00 +00:00 by agent-pi · 1 comment

agent-pi commented

2026-10-15 06:46:00 +00:00

Collaborator

A missing TMDB token should show up as an error in the process output, not be silently swallowed. The web process has the same gap around its own lifecycle.

Expected behaviour, standard for server applications:

errors (and anything more severe) appear on stdout
a log file records what the process is doing, down to a configurable level (all the way to DEBUG)
both the log file location and the level are configurable via XIQUE_* environment variables like every other setting

Found while manually testing the Trakt import flow: two recommend jobs failed and the worker gave no outward sign anything had happened.

When a background job fails — for example the recommend job without a TMDB token — the only record of the failure anywhere is the message stored in the jobs table. The worker process prints nothing, writes no log file, and an operator has no way to see what the worker is doing or why a job failed without querying the database directly. A missing TMDB token should show up as an error in the process output, not be silently swallowed. The web process has the same gap around its own lifecycle. Expected behaviour, standard for server applications: - errors (and anything more severe) appear on stdout - a log file records what the process is doing, down to a configurable level (all the way to DEBUG) - both the log file location and the level are configurable via XIQUE_* environment variables like every other setting Found while manually testing the Trakt import flow: two recommend jobs failed and the worker gave no outward sign anything had happened.

agent-pi commented

2026-10-15 06:46:59 +00:00

Author

Collaborator

Findings from the audit

grep -rn "import logging" src/ returns nothing: the entire codebase has zero logging. No getLogger, no handlers, no config.
worker.main() → asyncio.run(run_worker(...)) prints nothing, ever. _dispatch_job records failures via fail_job only; unexpected handler exceptions are swallowed into a generic token-free message and the traceback is dropped entirely.
server.main() is a bare uvicorn.run(...) — uvicorn logs requests, but nothing xique-specific (startup config, schema verification) is logged.
Verified against the live db: two recommend jobs sit in error status (XIQUE_TMDB_TOKEN is not configured) with no outward sign on the machine.

Plan of attack

Approach: stdlib logging, two sinks on the root logger, configured once per process from Settings.

Settings gains log_level: str = "INFO" (validated against the stdlib level names, case-insensitive) and log_file: Path | None = None → XIQUE_LOG_LEVEL, XIQUE_LOG_FILE.
New src/xique/logsetup.py with configure_logging(settings): a StreamHandler on stdout at ERROR, and — when log_file is set — a file handler at the configured level (DEBUG through CRITICAL). Format: timestamp, level, logger name, message.
Worker (worker.py): lifecycle + job logging — startup with db path/poll interval, stale-job recovery count, job started/completed (DEBUG), known job failures (WARNING, reusing the existing token-free fail_job message), unexpected handler exceptions at ERROR with traceback via logger.exception. Idle cycles stay quiet at INFO.
Web (server.py): call configure_logging before uvicorn.run, log schema-version verification and startup. Uvicorn keeps its own handlers; ours attach to the root without touching theirs.
README: document XIQUE_LOG_LEVEL and XIQUE_LOG_FILE (settings docs must stay in sync with config.py).

Tests (TDD, RED first): level routing (DEBUG reaches the file but not stdout; ERROR reaches both), log_file: None means stdout-only, invalid XIQUE_LOG_LEVEL rejected by Settings, worker failure logs at WARNING with the token-free message, unexpected handler exception logs traceback at ERROR, main() entry points call configure_logging.

Key files: src/xique/config.py, src/xique/logsetup.py (new), src/xique/worker.py, src/xique/web/server.py, README.md, tests/.

**Findings from the audit** - `grep -rn "import logging" src/` returns nothing: the entire codebase has zero logging. No `getLogger`, no handlers, no config. - `worker.main()` → `asyncio.run(run_worker(...))` prints nothing, ever. `_dispatch_job` records failures via `fail_job` only; unexpected handler exceptions are swallowed into a generic token-free message and the traceback is dropped entirely. - `server.main()` is a bare `uvicorn.run(...)` — uvicorn logs requests, but nothing xique-specific (startup config, schema verification) is logged. - Verified against the live db: two `recommend` jobs sit in `error` status (`XIQUE_TMDB_TOKEN is not configured`) with no outward sign on the machine. **Plan of attack** Approach: stdlib `logging`, two sinks on the root logger, configured once per process from `Settings`. 1. `Settings` gains `log_level: str = "INFO"` (validated against the stdlib level names, case-insensitive) and `log_file: Path | None = None` → `XIQUE_LOG_LEVEL`, `XIQUE_LOG_FILE`. 2. New `src/xique/logsetup.py` with `configure_logging(settings)`: a `StreamHandler` on stdout at ERROR, and — when `log_file` is set — a file handler at the configured level (DEBUG through CRITICAL). Format: timestamp, level, logger name, message. 3. Worker (`worker.py`): lifecycle + job logging — startup with db path/poll interval, stale-job recovery count, job started/completed (DEBUG), known job failures (WARNING, reusing the existing token-free `fail_job` message), unexpected handler exceptions at ERROR **with traceback** via `logger.exception`. Idle cycles stay quiet at INFO. 4. Web (`server.py`): call `configure_logging` before `uvicorn.run`, log schema-version verification and startup. Uvicorn keeps its own handlers; ours attach to the root without touching theirs. 5. README: document `XIQUE_LOG_LEVEL` and `XIQUE_LOG_FILE` (settings docs must stay in sync with `config.py`). Tests (TDD, RED first): level routing (DEBUG reaches the file but not stdout; ERROR reaches both), `log_file: None` means stdout-only, invalid `XIQUE_LOG_LEVEL` rejected by Settings, worker failure logs at WARNING with the token-free message, unexpected handler exception logs traceback at ERROR, `main()` entry points call `configure_logging`. Key files: `src/xique/config.py`, `src/xique/logsetup.py` (new), `src/xique/worker.py`, `src/xique/web/server.py`, `README.md`, `tests/`.

agent-pi referenced this issue

2026-10-15 06:46:59 +00:00

Phase 1 — hardening (deferred from 1a review) #7

agent-pi referenced this issue from a pull request that will close it,

2026-10-15 07:07:53 +00:00

Worker and web logging with configurable level and file #13

agent-pi closed this issue

2026-10-15 08:06:28 +00:00