Skip to content

fix(setup): deliver first-time setup token reliably to docker logs (#858) - #1168

Merged
vybe merged 2 commits into
devfrom
AndriiPasternak31/issue-858
Jun 16, 2026
Merged

fix(setup): deliver first-time setup token reliably to docker logs (#858)#1168
vybe merged 2 commits into
devfrom
AndriiPasternak31/issue-858

Conversation

@AndriiPasternak31

Copy link
Copy Markdown
Contributor

Problem

The first-time setup token was silently lost from docker logs, deadlocking fresh installs — it's the only documented path through the routers/setup.py token gate. docker/backend/Dockerfile had drifted and lost ENV PYTHONUNBUFFERED=1 (which docker/scheduler/Dockerfile still sets), so CPython block-buffered the lifespan's stdout into the ~8KB Docker log pipe and the printed token never surfaced.

Closes #858 (P1, type-bug, theme-devex).

Fix (two layers)

  1. Restore ENV PYTHONUNBUFFERED=1 in docker/backend/Dockerfile (parity with the scheduler image) — catches every print().
  2. Emit the setup token via logger.warning instead of print(). The logging StreamHandler flushes after every record, so the token is delivered regardless of buffering, survives future Dockerfile drift, and now flows through structured JSON logging / Vector. The token block is relocated to immediately after setup_logging(), before the event-bus/audit-write startup that could otherwise hang and suppress it. The remaining ~76 lifespan print() calls are converted to structured logger calls; setup_opentelemetry()'s import-time print stays print(flush=True) (it runs before setup_logging()).

Tests

Verified locally: test_858 (4 passed) + the 5 touched unit files (77 passed).

Notes / follow-up

🤖 Generated with Claude Code

@github-actions

Copy link
Copy Markdown

⚠️ Nightly unit-suite check skipped — merge conflict against dev.

Resolve by running git merge dev locally and pushing the result. The next nightly run will re-test once the conflict is gone.

AndriiPasternak31 and others added 2 commits June 12, 2026 22:41
The first-time setup token was block-buffered by CPython and never
reached `docker logs`, deadlocking fresh installs — the only documented
path through the setup token gate. docker/backend/Dockerfile had drifted
and lost `ENV PYTHONUNBUFFERED=1` (scheduler still set it), so lifespan
print() output sat in the ~8KB Docker pipe buffer.

Two-layer fix:
- Restore `ENV PYTHONUNBUFFERED=1` in docker/backend/Dockerfile (parity
  with docker/scheduler/Dockerfile) — catches every print().
- Emit the setup token via logger.warning (the StreamHandler flushes per
  record, so it survives future Dockerfile drift and flows through
  Vector), relocated to immediately after setup_logging() so a later
  startup hang can't suppress it. Convert the remaining lifespan print()
  calls to structured logger calls; setup_opentelemetry()'s import-time
  print stays print(flush=True) since it runs before setup_logging().

Adds unit/test_858_dockerfile_unbuffered.py: backend↔scheduler Dockerfile
parity guard + AST checks that the token is emitted via logger after
setup_logging() and that the lifespan has no print() calls.

Closes #858

Co-Authored-By: Claude <noreply@anthropic.com>
Discovered while running the full suite for #858 — unrelated to the
setup-token fix itself.

- test_agent_analytics / test_schedule_analytics: also restore
  `db.connection` and the `db` package's child-module attributes between
  tests. `import db.X` rebinds `db.X` on the package, and later files
  binding via `import db.X as Y` resolve through the package attribute,
  not sys.modules — restoring only sys.modules left them with a different
  module object than `from db.X import ...`, so attribute patches landed
  on the wrong module (the test_agent_soft_delete DB_PATH mismatch under
  randomized ordering).
- Refresh config/model stubs that predated newer features:
  VOIP_MAX_CALL_DURATION (#1091), GEMINI_TEXT_MODEL (#1138), and
  AgentDefaultAccessPolicyUpdate + agent_default_require_email (#1129).

Co-Authored-By: Claude <noreply@anthropic.com>
@AndriiPasternak31
AndriiPasternak31 force-pushed the AndriiPasternak31/issue-858 branch from 79c6681 to de0b329 Compare June 12, 2026 21:42
@AndriiPasternak31
AndriiPasternak31 requested review from dolho, pavshulin and vybe and removed request for dolho, pavshulin and vybe June 13, 2026 23:54
@AndriiPasternak31 AndriiPasternak31 self-assigned this Jun 13, 2026

@vybe vybe left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Validated & approved (/validate-pr)

P1 devex bug fix (Closes #858). 8 files, +358/-101.

Fix review (two layers, both sound):

  1. docker/backend/Dockerfile: restores ENV PYTHONUNBUFFERED=1 to parity with the scheduler image — root cause of the block-buffered print() swallowing the setup token. Clearly justified.
  2. main.py: setup token now emitted via logger.warning (StreamHandler flushes per record → immune to future Dockerfile drift, flows through Vector) and relocated to immediately after setup_logging(), before event-bus/audit startup that could hang and suppress it. The ~76 other lifespan print() → structured logger. setup_opentelemetry() import-time print correctly kept as print(flush=True) (runs before setup_logging()).

Tests: test_858_dockerfile_unbuffered.py (Dockerfile parity guard + AST checks: token via logger after setup_logging/before event_bus.start, no print() in lifespan). Feature flow first-time-setup.md + index + tests/registry.json updated.

  • Base → dev ✓ · conventional commits ✓ · CI all green
  • Security scan clean; no new env vars; Dockerfile change justified
  • (main.py flagged by the new-module COPY check is a false positive — it's the existing app entrypoint, not a new module.)

Notes (non-blocking):

  • Closing #858 is correct — the reported block-buffering bug is fixed. The residual prod --workers 2 per-worker-token flakiness is a genuinely distinct bug, correctly tracked as new issue #1165 (not conflated).
  • The 2nd commit's analytics-test changes (test_agent_analytics/test_schedule_analytics db-package-attr restoration) are unrelated test-isolation hygiene surfaced by running the full suite — test-only, well-commented, transparent. Acceptable.
  • Duplicate alert: #1180 (→main) targets the same #858 with the wrong base branch — close it in favor of this PR.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants