Skip to content

fix(api): log socket disconnects at the same level as connects - #9438

Open
lstein wants to merge 1 commit into
invoke-ai:mainfrom
lstein:fix/socket-lifecycle-logging
Open

fix(api): log socket disconnects at the same level as connects#9438
lstein wants to merge 1 commit into
invoke-ai:mainfrom
lstein:fix/socket-lifecycle-logging

Conversation

@lstein

@lstein lstein commented Aug 2, 2026

Copy link
Copy Markdown
Collaborator

Summary

Fix (logging/observability). Socket connects for authenticated clients are logged at INFO, while disconnects are logged at DEBUG:

logger.info(f"Socket {sid} connected with user_id: ...")   # INFO
logger.debug(f"Socket {sid} disconnected and cleaned up")  # DEBUG

With only half the lifecycle visible at the default log level, a client that reconnects in a loop is indistinguishable from sockets accumulating without bound. What it looks like in practice:

INFO --> Socket e8iM9z1hanEi7SpyAAD7 connected with user_id: 3c1a97cd-..., is_admin: True
INFO --> Socket JAbIf_OixHC9wpvuAAD9 connected with user_id: 3c1a97cd-..., is_admin: True
INFO --> Socket Q0JhvEVQFIiLFj3xAAD_ connected with user_id: 3c1a97cd-..., is_admin: True
...one per minute, forever

That reads like a leak. It was actually a forgotten browser tab on an idle machine: the browser had throttled its timers to roughly one wake per minute, so the socket died and was re-established on that cadence. Diagnosing it took a TCP-level packet-state capture on the server, which is a silly amount of work for a question the log should have answered directly.

The change: log the disconnect at the same level as the matching connect (INFO for token-authenticated sockets, DEBUG for the single-user path, mirroring the two halves of _handle_connect), and include python-socketio's disconnect reason. With this, the same incident reads:

INFO --> Socket e8iM9z1hanEi7SpyAAD7 connected with user_id: 3c1a97cd-..., is_admin: True
INFO --> Socket e8iM9z1hanEi7SpyAAD7 disconnected (user_id: 3c1a97cd-..., reason: ping timeout)

reason is one of ping timeout, transport close, transport error, client disconnect, server disconnect — the first thing worth knowing when sockets churn, and it distinguishes a throttled/asleep client from a network problem from a deliberate client teardown.

Note the default log level is unchanged for a default (single-user) install: useSocketIO.ts sends no token in single-user mode, so those sockets take the authenticated: False branch and both halves stay at DEBUG. Only multiuser deployments — which already log every connect at INFO — gain a line.

Related Issues / Discussions

None.

QA Instructions

Multiuser mode (multiuser: true):

  1. Start the server, log in, confirm Socket ... connected with user_id: ... at INFO as before.
  2. Close the tab. A matching Socket ... disconnected (user_id: ..., reason: client disconnect) should appear at INFO.
  3. To see a non-trivial reason, background the tab on a machine that aggressively throttles timers, or kill the network path; the disconnect should report ping timeout or transport close.

Single-user mode: both connect and disconnect stay at DEBUG. Run with log_level: debug to confirm the pair appears, and at the default level to confirm neither does.

Automated: pytest tests/app/test_workflow_socketio.py tests/app/routers/test_multiuser_authorization.py — 4 new tests cover the INFO pairing, the DEBUG pairing, an unknown sid, and a call without a reason argument.

Merge Plan

Ordinary merge, no migrations, no schema changes.

Notes for reviewers

Two constraints on _handle_disconnect's body are documented in its docstring because they are non-obvious and easy to break in a later edit — both were found by adversarially reviewing this diff against the installed python-socketio:

  • It must not raise. AsyncServer._handle_disconnect does not guard its _trigger_event call, so an exception in this handler skips manager.disconnect() and leaks the sid's room membership and server.environ entry for the life of the process. Hence .get() rather than subscripting the per-socket dict, whose shape is enforced only by convention.
  • The pop must stay first. _trigger_event retries disconnect handlers on TypeError with one fewer argument, and that retry wraps the await of the handler, not just the argument binding — so a TypeError raised anywhere in the body would silently re-enter the method. Popping first makes the re-entry a no-op.

reason keeps a None default because python-socketio is unpinned in pyproject.toml; versions before 5.12 call the handler with sid alone.

Out of scope, but found while reviewing this: _handle_sub_queue can resurrect a popped _socket_users entry. AsyncServer.async_handlers defaults to True, so subscribe_queue runs as a background task whose is_connected check happened before the task was scheduled; if the transport dies in between, the disconnect pops the entry and the queued task then recreates it at the single-user fallback, where nothing will ever pop it again. The stale sid then pollutes every subsequent skip_sid list. It predates this PR and is untouched here — happy to file it separately.

Checklist

  • The PR has a short but descriptive title, suitable for a changelog
  • Tests added / updated (if applicable)
  • ❗Changes to a redux slice have a corresponding migration — n/a
  • Documentation added / updated (if applicable) — n/a
  • Updated What's New copy (if doing a release after this PR) — n/a

Socket connects for authenticated clients were logged at INFO while
disconnects were logged at DEBUG. With only half the lifecycle visible, a
client that reconnects in a loop — a backgrounded browser tab whose timers
have been throttled, a flaky network — is indistinguishable in the log from
sockets accumulating without bound.

Log the disconnect at the same level as the matching connect, and include
python-socketio's disconnect reason (`ping timeout`, `transport close`, ...),
which is the first thing worth knowing when sockets are churning.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

api python PRs that change python files python-tests PRs that change python tests

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant