Skip to content

Fix logging path that panics a connection task and wedges the proxy (#21) - #23

Merged
solidcitizen merged 4 commits into
mainfrom
fix/issue-21-logging-wedge
Sep 18, 2026
Merged

solidcitizen merged 4 commits into
mainfrom
fix/issue-21-logging-wedge

Conversation

@solidcitizen

Copy link
Copy Markdown
Owner

Fixes #21. Release 1.0.5 (#21 only; #15/#14 follow).

The defect

Logging was on the connection data path. pgvpd logs to stdout via tracing_subscriber::fmt, and a per-connection info! ("tenant connection", early in the handshake) wrote directly on the connection task. When a parent process closed both pgvpd's stdout and stderr while pgvpd kept running (a launcher that exited right after spawn, or a supervisor that stopped draining piped stdio), the stdout write failed with EPIPE, tracing-subscriber's error fallback eprintln!'d to the now-closed stderr, and eprintln! panics on a write error. That panic unwound out of the info! call inside the spawned per-connection task, so the task died before Metrics::dec(connections_active) and before checkout. Every later connection was then accepted and dropped (Connection terminated unexpectedly), connections_active climbed and never fell, and pool checkouts froze — a permanent wedge (TCP still accepting, /status still serving, process alive) cleared only by restart.

Pre-existing (1.0.0–1.0.4). This is the wedge behind the original field report; #20 (fixed in 1.0.4) was a separate slot-accounting leak.

The fix

Log through tracing_appender::non_blocking — a bounded channel drained by a dedicated worker thread (lossy: drops lines when full). Connection tasks only push to the channel; the worker does the actual write, so a slow or closed consumer can neither block nor panic a connection task. The startup banner and fatal-error line use non-panicking writes.

Verification

  • cargo fmt --check, cargo clippy -- -D warnings, cargo test (94 unit tests) — green.
  • ./tests/run.sh 53/53, including new Suite 10: spawn pgvpd with piped stdout+stderr, warm up, destroy both pipes, then assert connections still succeed and connections_active does not leak.
  • Red-then-green: red on 1.0.4 (9/9 post-close connects "terminated unexpectedly", active leaked to 9), green on the fix (9/9 ok, active 0).

Bumps version to 1.0.5.

)

pgvpd logged to stdout via tracing_subscriber::fmt, and a per-connection
info! ("tenant connection", early in handshake) wrote directly on the
connection task — logging was on the data path. When a parent process closed
BOTH pgvpd's stdout and stderr while pgvpd kept running (a launcher that
exited right after spawn, or a supervisor that stopped draining piped stdio),
the stdout write failed with EPIPE, tracing-subscriber's error fallback
eprintln!'d to the now-closed stderr, and eprintln! panics on a write error.
That panic unwound out of the info! call inside the spawned per-connection
task, so the task died before Metrics::dec(connections_active) and before
checkout. Every subsequent connection was then accepted and dropped
("Connection terminated unexpectedly"), connections_active climbed and never
fell, and pool checkouts/creates froze — a permanent wedge (TCP still
accepting, /status still serving, process alive) cleared only by restart.

Pre-existing (1.0.0-1.0.4). This is the wedge behind the original field
report; #20 (fixed in 1.0.4) was a separate slot-accounting leak.

Fix: log through tracing_appender::non_blocking — a bounded channel drained
by a dedicated worker thread (lossy: drops lines when full). The connection
tasks only push to the channel; the worker does the actual write, so a slow
or closed consumer can neither block nor panic a connection task. The startup
banner and the fatal-error line now use non-panicking writes (writeln! to
stderr, error ignored) instead of eprintln!.

Regression coverage (Suite 10, tests/drizzle/log-wedge.mjs): spawn pgvpd with
piped stdout+stderr, warm up, destroy both pipes, then assert connections
still succeed and connections_active does not leak. Verified red on 1.0.4
(9/9 post-close connects "terminated unexpectedly", active leaked to 9) and
green after (9/9 ok, active 0).

Bump version to 1.0.5.
@chatgpt-codex-connector

chatgpt-codex-connector Bot commented Sep 18, 2026 •

Copy link
Copy Markdown

Codex Review Summary

This comment shows the latest Codex review activity on this pull request.

Review Status Commit Review trigger
📝 Code Review ✅ Completed 2026-09-18T08:46:41.070031Z 139577a PR opened
ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

The harness used a fixed 1000ms sleep before probing the spawned pgvpd, which
raced its startup on slow/cold CI runners (ECONNREFUSED before the pipe close
→ false setup failure). Poll the proxy port until it accepts, up to 20s, and
loosen the active-leak threshold with a settle delay so a connection mid-close
does not false-fail. No change to the fix or the assertions' intent.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 139577a7e1

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".

Comment thread Cargo.lock
Comment on lines +1092 to +1093
name = "time"
version = "0.3.55"

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P1 Badge Keep the dependency compatible with the Docker toolchain

The newly locked time 0.3.55 requires a Rust compiler newer than 1.85, but the checked-in Docker build still uses rust:1.85-slim (Dockerfile:1) and runs cargo build --release. Consequently, every build of the provided Dockerfile now fails Cargo's rust-version check before compiling; upgrade the builder toolchain or resolve tracing-appender/time to versions compatible with Rust 1.85.

Useful? React with 👍 / 👎.

Michael Conant added 2 commits September 18, 2026 01:53
…iagnostics

Suite 10 failed on CI with 'proxy never came up' while passing locally — the
harness spawned pgvpd on 16432/16433, the same ports the prior suite used, and
on the CI runner the port was not always released in time, so the harness's
pgvpd failed to bind and exited. Use dedicated ports (16442/16443, overridable)
so the suite can't race another suite's pgvpd, and capture the child's stderr
and spawn errors so a startup failure is visible instead of a bare timeout.
Root cause of the CI-only 'proxy never came up' failure: the harness built the
child pgvpd's env by spreading process.env, and run.sh passed PGVPD_HOST=$PG_HOST
as the upstream host — but PGVPD_HOST is pgvpd's own LISTEN host. On CI PG_HOST
is 'localhost', so the child listened on localhost (::1 on the runner) while the
harness probed 127.0.0.1 (IPv4); locally PG_HOST was 127.0.0.1 so it passed.

Set PGVPD_HOST='127.0.0.1' explicitly in the child env (listen host), and pass
the upstream host/port under non-colliding names (WEDGE_UP_HOST/WEDGE_UP_PORT),
normalizing 'localhost' to 127.0.0.1 to avoid the IPv4/IPv6 mismatch. Verified
by reproducing the CI env locally (leaked PGVPD_HOST=localhost) — now green.
@solidcitizen
solidcitizen merged commit 222999f into main Sep 18, 2026
3 checks passed
@solidcitizen
solidcitizen deleted the fix/issue-21-logging-wedge branch September 18, 2026 09:01
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.

Logging on the connection path panics the task when stdout AND stderr are closed, permanently wedging the proxy

1 participant