ux verify --contracts --managed: empty-error RBAC failures on ops_dashboard (Bug A: false failure, Bug B: unloggable error)

[manwithacat]

Symptom

$ cd examples/ops_dashboard
$ dazzle ux verify --contracts --managed
Generated 30 contracts
Running contract verification...
Contracts: 16 passed, 2 failed, 12 pending
  FAIL rbac:Alert:ops_engineer:list — 
  FAIL rbac:Alert:ops_engineer:create — 

Two RBAC contracts fail. Error messages are empty (the line is FAIL rbac:Alert:ops_engineer:list — with nothing after the em-dash). The same --contracts run against a live dazzle serve --local --test-mode server (no --managed) reports 18 passed, 0 failed, 12 pending.

The 2 contracts were generated by a recent contract-generation pass (count grew 28 → 30 between cycle 107 and now) and target the persona ops_engineer's ability to list/create Alert.

Direct managed-mode repro shows the behaviour is correct

import asyncio
from pathlib import Path
from dazzle.e2e.runner import ModeRunner
from dazzle.e2e.modes import get_mode
from dazzle.testing.ux.htmx_client import HtmxClient

async def run():
    async with ModeRunner(
        mode_spec=get_mode("a"),
        project_root=Path("examples/ops_dashboard"),
        personas=["ops_engineer"],
        db_policy="fresh",
    ) as conn:
        client = HtmxClient(base_url=conn.site_url)
        ok = await client.authenticate("ops_engineer")
        # auth_ok = True
        resp = await client.get_full_page("/app/alert")
        # status=200, html_len=5080
        # HAS 'data-dazzle-table'
        # HAS '/alert/create'

asyncio.run(run())

The same ModeRunner substrate the CLI uses, the same auth call, the same persona — returns 200 with both data-dazzle-table="Alert" and <a href="/app/alert/create"> present. _check_rbac should find both markers and mark passed.

But the CLI's dazzle ux verify --contracts --managed reports them as failed with an empty error.

Two distinct bugs

Bug A — wrong status

The contracts shouldn't fail. The underlying app is rendering correctly for ops_engineer. Possible causes:

1. The CLI's RBAC loop in src/dazzle/cli/ux.py:308-365 creates a fresh HtmxClient per persona (persona_client = HtmxClient(base_url=site_url)), authenticates, then checks. Maybe the session cookie isn't persisted across the auth → fetch sequence in some managed-mode environment.
2. Maybe the managed-mode subprocess does some cleanup that invalidates the session between auth and the GET (e.g., per-test DB reset, port re-allocation).
3. Maybe _get_permitted_personas (line 308 region) is filtering out ops_engineer incorrectly, causing the contract to be checked with expected_present=False while the page actually renders the markers — but then errors would say "expected absent, but found" which is non-empty.

Bug B — empty error message

Per src/dazzle/testing/ux/contract_checker.py:707-712:

if errors:
    contract.status = "failed"
    contract.error = "; ".join(errors)
else:
    contract.status = "passed"
    contract.error = None

A "failed" status MUST come with a non-empty error message — "; ".join([]) is "" but the else-branch sets status="passed" first. So the empty error implies the contract was set to status="failed" outside check_contract with error="".

The most likely candidate is line 365: rc.error = str(e) inside except Exception as e. Some exception's __str__ returns "". Possible culprits: requests or httpx exceptions where the message is in .args[0] not str, or a raised Exception("") somewhere in the stack.

This is a logging-clarity bug regardless of bug A: a FAIL with no error message is unactionable.

Repro environment

• Branch: main (commit c1a04a6, v0.67.146)
• Python 3.12.11
• macOS 25.5.0 (darwin)
• Triggered by /improve cycle 118-119 ux-converge sweep — see dev_docs/improve-backlog.md Lane: ux-converge row for ops_dashboard.

Suggested fix path

1. Add a print(f"DEBUG check_contract({contract.contract_id}) → status={status}, error={error!r}") near src/dazzle/cli/ux.py:382 and re-run managed mode to confirm which code path is setting status without a message. Promote to proper logging once located.
2. Wrap the try/except at src/dazzle/cli/ux.py:362-365 with a guard that synthesises a fallback error when str(e) is empty (rc.error = str(e) or f"{type(e).__name__}: <no message>").
3. Trace bug A from the debug trace's source.

Discovered by

/improve cycle 119 ux-converge lane. ops_dashboard regressed 0 → 2 contract failures between cycle 107 and 118; cycle 119's CONVERGE step tried to root-cause and found that the runtime behaviour is correct, the contract plumbing is what's broken.

[github-actions]

Thanks for opening this issue, @manwithacat!

Next Steps

This issue would benefit from AI-assisted investigation. You can:

1. Assign to Copilot: Click "Assignees" and select @copilot to have GitHub Copilot investigate and create a PR
2. Investigate with AI: Use Claude, ChatGPT, or another AI to help analyze the issue and update your description

Copilot Assignment

When you assign this issue to Copilot, it will:

• Explore the codebase to understand the context
• Create a draft PR with proposed changes
• Run tests and linting automatically

See our contribution guidelines for more details.

[manwithacat]

Cycle 134 update — Bug A root cause clarified

Bug B (empty error → diagnostic class name) shipped in v0.67.148 and is working. The next-run output now shows:

RBAC contract for Alert/ops_engineer/list raised empty ReadTimeout

— httpx.ReadTimeout. Direct repro via ModeRunner substrate (same path the CLI uses) shows /app/alert as ops_engineer returns 200 in 40ms. So Bug A is not about response latency.

The actual mechanism: managed-mode subprocess leaks postgres: idle in transaction sessions when a previous run is killed (CI timeout, Ctrl+C, signal). The next ux verify --contracts --managed boots a new subprocess, but the leaked PG sessions are still holding CREATE INDEX waiting locks on dazzle_ops_dashboard. The fresh subprocess's contract queries block waiting on those locks. From httpx's view, the connection accepts the request and never responds → ReadTimeout fires (at whatever ceiling — 10s, 30s, or 60s, the wait is unbounded).

Reproduction trail:

$ ps aux | grep "dazzle serve" | grep -v grep
james 50005 ... dazzle serve --local   <- leaked from prior run

$ ps aux | grep "dazzle_ops_dashboard"
postgres 50452 ... CREATE INDEX waiting
postgres 50015 ... idle in transaction  <- holds locks

Bumping the httpx timeout to 60s did NOT fix this — the run still hung, because the locks are held indefinitely. The only "fix" is to kill the leaked server PIDs by hand or run pg_terminate_backend() on the idle transactions before each managed-mode start.

Real fix paths

Three options:

1. ModeRunner-side cleanup on enter — before starting the subprocess, scan pg_stat_activity for idle in transaction sessions on the project's database and pg_terminate_backend(pid) them. Adds a one-time cleanup pass to every managed-mode start. Side effect: any genuinely-running concurrent migration would also be killed, so guard with a "matches dazzle subprocess" filter if possible.

2. ModeRunner-side cleanup on exit — register an atexit / signal handler that explicitly closes all DB connections held by the subprocess before letting the OS reap it. The current cleanup is uvicorn's default which doesn't always finalise the SQLAlchemy session pool.

3. Subprocess hardening — dazzle serve --test-mode should install a SIGTERM/SIGINT handler that synchronously closes the session pool. Currently --test-mode doesn't have one.

(1) is the safest band-aid; (2) is the right architectural fix; (3) would prevent the leak in the first place.

Workaround until then

Before each managed-mode contract run:

# Find and kill any leaked dazzle serve subprocesses
pkill -f "dazzle serve --local"  # then wait a few seconds for PG sessions to clear
psql -d dazzle_ops_dashboard -c "SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE state = 'idle in transaction';"

The 30s httpx timeout in HtmxClient is kept as-is in v0.67.148; it correctly covers the legitimate cold-start case but cannot defend against indefinite lock waits.

Status

• Bug B: CLOSED in v0.67.148 (commit 6756cc7).
• Bug A: still open. Filed three fix-path proposals above. Recommend (1) as the smallest-step landing.

[manwithacat]

v0.67.153 ships fix path (1) — defensive cleanup on ModeRunner enter/exit

Commit: d4692550. New module src/dazzle/e2e/_pg_cleanup.py with terminate_stale_sessions(database_url) -> int. Hooked into ModeRunner.__aenter__ (before _apply_db_policy) and __aexit__ (before lock release). Dotenv-aware so per-project DATABASE_URL is found the same way the subprocess finds it.

5 regression tests in tests/unit/e2e/test_pg_cleanup.py. 13,991 unit tests pass.

What this closes

The dead-process case: a previous dazzle serve --local was killed (CI timeout, Ctrl+C, OOM, etc.), its OS process is gone, but its PG sessions are still idle in transaction holding locks. The next managed-mode run now terminates those sessions before its own subprocess boots → migrations no longer block.

What this does NOT close

The live-leaked-process case (still observed locally):

• An operator runs dazzle serve --local manually in another terminal, forgets to kill it.
• That process has an outbox publisher loop polling _dazzle_event_outbox in a transaction.
• Cleanup terminates the session → publisher detects the connection error → publisher immediately reconnects and opens a new transaction → cleanup is racing against a live producer.

Reproduced with PID 50005 still running during cycle 134 verification — even after the cleanup ran, pg_stat_activity immediately showed PID 50015 back in idle in transaction with query_start matching cycle 134's wall-clock.

Path forward — fix (3) from the original issue body

dazzle serve --test-mode (and arguably --local too) should install a SIGTERM/SIGINT handler that:

1. Cancels all active asyncio tasks
2. Synchronously awaits engine.dispose() to close the SQLAlchemy session pool
3. Closes httpx clients / event-bus connections
4. Then lets uvicorn's own shutdown drain

This prevents the leak in the first place. Once that ships, the cleanup helper in v0.67.153 becomes pure belt-and-braces — useful for SIGKILL / OOM where signal handlers don't run, but not the only line of defense.

Operator workaround until then:

# Find any orphan dazzle serve processes
ps aux | grep "dazzle serve --local" | grep -v grep
# Kill them by PID
kill <pid>
# Then re-run managed-mode contracts; the v0.67.153 cleanup catches their residual sessions

Recommend leaving #1072 open with the "Bug A partial — needs subprocess hardening" tag until fix (3) lands.

[manwithacat]

Real Bug A is different from the leaked-session hypothesis

After killing the live-leaked PID 50005 (the workaround), dazzle ux verify --contracts --managed against ops_dashboard still fails the same 2 contracts with ReadTimeout. PG state at time of failure shows ONLY the fresh managed-mode subprocess's normal outbox-publisher idle-in-transaction — no foreign leaks. v0.67.153's defensive cleanup runs but doesn't help.

Critical bisection finding:

$ dazzle ux verify --contracts --managed                    # all personas
Contracts: 16 passed, 2 failed, 12 pending
  FAIL rbac:Alert:ops_engineer:list — ReadTimeout: <no message>
  FAIL rbac:Alert:ops_engineer:create — ReadTimeout: <no message>

$ dazzle ux verify --contracts --managed --persona ops_engineer
Contracts: 14 passed, 0 failed, 8 pending     <-- ALL GREEN

The ops_engineer Alert.list and Alert.create contracts pass in isolation. They fail only when admin's contracts run first. This is an in-process accumulation bug, not a cross-run leak.

New hypothesis

The contract verifier runs admin's contracts first (the implicit fallback at cli/ux.py:198), which fetches many URLs as admin: workspace composites, list pages, detail views, edit forms. Each request acquires a DB connection from the pool. By the time ops_engineer's RBAC batch starts, either:

1. DB connection pool is exhausted/starved — ops_engineer's fresh HtmxClient.get_full_page waits for a connection that's held by admin's still-in-flight requests
2. Lock contention on a shared table — User table (where /__test__/authenticate writes), event-outbox, audit_entry
3. Test-mode auth path holds session lock — each /__test__/authenticate creates/updates a user, possibly blocking ops_engineer's auth-then-fetch under load
4. The fresh HtmxClient per persona uses no connection reuse — each request reopens an httpx.AsyncClient, accumulating ephemeral connections that the server can't drain fast enough

v0.67.153 status

The defensive cleanup helper in src/dazzle/e2e/_pg_cleanup.py is still useful — it handles the original "killed previous run leaves idle-in-tx behind" scenario. That code path is now wired into both ModeRunner AND launch_interaction_server (in this commit). But it doesn't address the within-run accumulation that produces the failures the user originally reported.

Recommend leaving Bug A open with the partial-fix tag. The full fix needs investigation along the 4 hypotheses above. Quickest win is likely (1) — diagnose the connection pool exhaustion (check dazzle serve's SQLAlchemy pool_size + max_overflow, time how long admin's contracts hold connections, see if pool_pre_ping is on).

Operator workaround: run with --persona <name> for each persona separately. Slower but reliable. The "all personas at once" path is what hangs.

Cycle 134 wrap-up.

[manwithacat]

Hypothesis 1 (DB connection pool starvation) — RULED OUT

Tested directly:

$ DAZZLE_DB_POOL_MAX=30 dazzle ux verify --contracts --managed
Contracts: 16 passed, 2 failed, 12 pending     (same failure)

A 3× larger pool does not change the outcome. Pool exhaustion is not the cause.

Confirmed pool config inventory while investigating:

• Main pool: psycopg_pool.ConnectionPool (src/dazzle/back/runtime/pg_backend.py:169), default min=2, max=10, env-configurable via DAZZLE_DB_POOL_MIN/MAX
• Event framework: separate dedicated psycopg.AsyncConnection per outbox publisher + per consumer (1-3 connections, not in main pool)
• Startup transients: metadata.create_all(engine) + _apply_search_indexes use throwaway engines that dispose() afterward

Per-process footprint: ~14 connections. With max=30, the pool was 3× over-provisioned for a sequential single-client request stream — no contention possible.

Documentation landed

While investigating, found that the existing pool docs in docs/guides/heroku.md and docs/reference/databases.md didn't account for the +4 non-pool framework connections. The (POOL_MAX) × WEB_CONCURRENCY < max_connections formula was incomplete — should be (POOL_MAX + 4) × WEB_CONCURRENCY < max_connections - 5.

Updated both docs in this commit to land:

• Corrected per-process budget (≈14 connections, not just POOL_MAX)
• Heroku TCP idle-timeout note (30 min — relevant for production)
• Diagnostic command cheat-sheet (heroku pg:info, pg_stat_activity queries)
• Symptom → fix table including the "CREATE INDEX waiting" pattern that matches Bug A's adjacent class

Remaining hypotheses on Bug A

1. Pool starvation — RULED OUT (this comment)
2. Lock contention on shared tables (User writes during /__test__/authenticate, audit_entry inserts during request handling, event-outbox row locks)
3. Test-mode auth path holds session lock — each call creates/updates a user; concurrent personas may contend
4. httpx.AsyncClient per-call connection leak — async with httpx.AsyncClient() as client: recreates a fresh client per HtmxClient method, accumulating ephemeral TCP connections that the server's uvicorn worker can't drain

Next most-fruitful probe: (2) lock contention. Specifically, hook a logger into _authenticate_test_user to confirm whether ops_engineer's auth succeeds before the GET, and time both. If auth takes >5s when admin's contracts have just finished, the User table is the likely contention point.