chore: quiet the log - demote routine chatter, add identity to per-connection warns - #31
Draft
petergaultney wants to merge 4 commits into
Draft
Conversation
Eight info/warn-level lines that fire on routine traffic rather than on anything an operator would act on: - "Loading doc" (both call sites) and "evicting doc" - once per doc per load/evict cycle, which on a fleet of active docs is continuous. - "Generating file upload URL" / "Generating file download URL" - one line per request. - "Webhook sent successfully" - one line per delivered event. - "Pong timeout (observe-only)" - fires for every connection a client drops without a close handshake, which is the normal case for a laptop closing its lid. The metric still records it. - "Registered client_id for user via server-driven PUD" - once per client per doc. - "Received awareness update with more than one client" was a warn, but a relaying client forwards awareness for its peers, so a multi-client update is ordinary protocol traffic and not an anomaly. On a ~40-user deployment these dominate the log at info, so anything info-level that does need attention is buried. All of them remain at debug for when a specific doc or request is being traced.
Three follow-ons to the backpressure work already on main: - A connection's start and end. `handle_socket_inner` logged nothing when a websocket ended - the close reason was computed for metrics and then discarded. An info-level "WebSocket disconnected" now reports doc_id, user, close_reason, and duration_secs, which makes reconnect loops and short-lived connections visible in the log rather than only in aggregate metrics. The matching "WebSocket connected" is debug, since the disconnect line already carries the duration. - A periodic re-warn while the outbound channel stays full. The transition warns say a client went wedged and later recovered, but between them there is silence, so a client wedged for six hours looks the same as one wedged for ten seconds until it recovers. The re-warn fires every five minutes with the running drop count and full_secs. - doc_id and user on the read-loop warns (non-binary message, message handling errors) and user on the five awareness/subscription warns in doc_connection.rs. These fire per-connection, and without identity there is no way to tell which client is misbehaving. All fields are ids, not names.
The sync bots open one socket per doc, sync, and close - thousands of sub-second sessions per reconnect storm, which buried every other info line. A connection that actually lived is still logged at info; the instant ones drop to debug.
Clients cycle a websocket per open document every minute or two, so a clean close is background noise - 190 of 199 lines in a ten-minute sample, across 25 docs and every active user, which buried the edit-attribution lines the log exists for. A close the client requested says nothing an operator would act on. The four reasons that do - sink_error, stream_eof, token_expired, server_shutdown - stay at info and are currently silent in production. Clean closes remain at debug and in the close metric. The previous threshold demoted only sub-second sessions, on the assumption the noise was bot traffic; the real volume is ordinary multi-minute client cycling.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
🍋: drafted by an AI assistant working with @petergaultney
Log-volume work, no behavior changes. On our ~40-user deployment the info level is dominated by lines that fire on routine traffic, so the info-level lines that do need attention are buried. This demotes those, and adds identity to the per-connection warns that remain so an operator can act on them.
This supersedes #18, which was partly merged as fa1d3c9 (
chore: quiet per-doc chatter, contextualize backpressure and awareness warns). Only #18's unmerged remainder is here, rebased on current main; #18 will be closed.Commit 1 - demote per-doc and per-request chatter to debug
Seven info-level lines, all still available at debug:
Loading doc(both call sites),evicting docGenerating file upload URL,Generating file download URLWebhook sent successfullyPong timeout (observe-only)Registered client_id for user via server-driven PUDThe pong-timeout metric still records regardless of log level.
One warn is demoted too:
Received awareness update with more than one client. A relaying client forwards awareness for its peers, so a multi-client update is ordinary protocol traffic, not an anomaly - the single-client case is simply the one from which this connection can attribute aclient_id.Commit 2 - connection lifecycle logs and context on the warns that survive
handle_socket_innerlogged nothing when a websocket ended - the close reason was computed for metrics and then discarded. An info-levelWebSocket disconnectednow reportsdoc_id,user,close_reason, andduration_secs. That makes reconnect loops and abnormally short connections visible in the log, not only in aggregate metrics. The matchingWebSocket connectedis debug, since the disconnect line already carries the duration.The backpressure transition warns on main say a client went wedged and later recovered, but between them there is silence - a client wedged for six hours looks identical to one wedged for ten seconds until it recovers. A re-warn now fires every five minutes (
CHANNEL_FULL_REWARN) with the running drop count andfull_secs.doc_idanduserare added to the two read-loop warns (non-binary message, message-handling errors) anduserto the five awareness/subscription warns indoc_connection.rs. These fire per-connection and were contextless.On identity in log lines
Every field added here is an id (
useris the relay user id,doc_idthe doc id) - nothing derived from a file name or a display name. The name-bearing logging is separate and gated behind a config flag that defaults to off; see #24.Relationship to the other open PRs
Independent - this branches straight off
mainand contains only log-volume work.#23 and this PR both touch the
Received awareness update with more than one clientline - this one changes its level, #23 adds adoc_idfield. Whichever merges second takes a one-line textual conflict; there is no semantic disagreement. #22 is independent of all of these.237 tests pass;
cargo fmt --checkclean.