Skip to content

fix: log only replies that were sent, keep the drain line after a second signal, skip logging work when off #104

Closed

Description

@cristiangirlea

Found by an independent review of the structured logging (#75, PR #91) and the per-owner cap (#76, PR #98) after they merged; checked against main at d3c6253. None of these leaks anything: the log's schema and its value checks hold. They make a line say something that did not happen, or leave a case untested.

Defects

  1. A reply that was never delivered can be logged as sent. Handler.send_response (worker/ai_bridge/server.py) records _status before the status line and headers are written, and handle_one_request logs from its finally. If the client resets during the write, the line still says, for example, 200, with no reply delivered. Likewise BridgeServer.process_request logs the busy 503 even when its non-blocking send(BUSY) raised. Fix: record a reply as sent only after its body is written (in _send and the 431 path), and log the busy 503 only when the send succeeded; otherwise log no request line, as for a connection that ends before any reply.
  2. The drain line can still be lost after a second signal. BridgeServer.server_close waits only join(1) for the drain thread. If that thread is held longer, for instance by a slow snapshot() on a busy store, jobs.close(), the stop line and log.close() can run before it writes drain. Fix: have the drain thread publish its result (an Event plus the computed fields) before it calls shutdown(), and let server_close write the drain line from that result if the thread has not, so the line is always written once, before stop.
  3. With BRIDGE_LOG=off, request handling still does logging work. The per-request timer, _method()/_route() and the job timings in JobStore._finish run before log.event() checks that logging is on, and the drain takes a snapshot() only for its line. Nothing is written, so this is cost, not output. Fix: a cheap log.enabled() check at those call sites.

Missing tests

  • Item 1: a reply whose first write fails writes no request line, and neither does a failed busy send.
  • Item 2: a drain thread held for longer than one second still writes exactly one drain line, with interrupted: true, before stop.
  • Item 3: with logging off, the field construction is skipped, not just the output.
  • Captured JSON lines for a 429 and for the 503 draining, with their status, owner, schema and the sentinel's absence.
  • The owner cap with cancelled jobs: concurrency 1, owner cap 2 and a larger capacity. One job running and one queued, so the next submit is refused. Cancel both: the owner stays at its cap, because cancelled jobs are retained, while another owner still submits. Expire one cancelled job: exactly one slot returns.

Files: worker/ai_bridge/server.py, worker/ai_bridge/jobs.py, worker/ai_bridge/log.py, tests/python/test_server.py, tests/python/test_jobs.py, tests/python/test_log.py, and docs/protocol.md if the Logging section's wording on which replies get a line changes.

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions