fix(cubestore): Report a websocket peer that goes away as debug, not error - #11786
Conversation
…error A client that closes without a close handshake ends the connection the same way a graceful one does: the driver terminates connections by design on a heartbeat timeout, a write error and on dispose, and a killed process or a closed browser tab looks the same. Every one of those was logged as an error, so a rolling restart of the API produced one error line per connection and pushed the error rate of a healthy node over its alerting threshold. Classify the read-stream error instead: a vanished peer is reported at debug, a frame arriving after the peer's own close frame at warn, and everything else -- other protocol violations, TLS, capacity and IO errors that are not a vanished peer -- stays at error. IO errors are split by kind rather than lowered as a group, so a genuine failure of the connection is still an error.
github-actions
Bot
added
cube store
|
Claude finished @waralexrom's task in 1m 55s —— View job Review: approach is sound — 1 medium (send path still logs vanished peers at
|
| # | Severity | Location | Issue |
|---|---|---|---|
| 1 | Medium | mod.rs:530, 541, 567 | Send-path errors still log at error. A peer that goes away mid-query hits Websocket message send error with ConnectionClosed/Io(BrokenPipe), so the rolling-restart scenario the PR targets can still emit one error line per connection. Routing those three sites through the same websocket_error_level would close the gap — the classifier is already direction-agnostic. |
| 2 | Low | mod.rs:155–166 | The 11-line doc block exceeds the repo's 3-line guidance for explanatory comments, repeats the source() sentence verbatim from mod.rs:115, and restates the commit message. The four inline blocks in tungstenite_error_level are similar; the _ => one mostly re-lists the arms above it. |
Notes, not blocking
ConnectionClosed/AlreadyClosed are listed defensively for a future tokio-tungstenite bump — worth keeping, and the comment says as much. After this change a connection ending abnormally is invisible at the default info level; that's the intent, but if connection-lifecycle visibility matters operationally, a single debug! on loop exit would be a cheaper place to get it than an error per disconnect.
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
Codecov Report✅ All modified and coverable lines are covered by tests.
Additional details and impacted files@@ Coverage Diff @@
## master #11786 +/- ##
===========================================
- Coverage 84.67% 60.16% -24.51%
===========================================
Files 261 239 -22
Lines 86451 19203 -67248
Branches 0 3886 +3886
===========================================
- Hits 73204 11554 -61650
+ Misses 13247 7099 -6148
- Partials 0 550 +550
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
A connection breaks in both directions. A peer that goes away with a query in flight fails the send instead of the read, and the send towards a peer that already closed reports it as `ConnectionClosed`, `AlreadyClosed` or `Io(BrokenPipe)` -- so one error line per connection was still logged for a client that merely left. Route every write towards the peer through the same classifier, which never depended on the direction. Also drop the comments that restated the arms they sit on.
|
Claude finished @waralexrom's task in 1m 39s —— View job Re-review after
|
…_threshold The test imported a CSV over HTTP from a third-party host, which refuses automated downloads, so the table was never created and the test failed wherever egress is not allowed. The location only ever contributed its size: the threshold under test comes from `estimate_rows`, which divides the file size by a fixed average row length without reading the file. Generate the CSV locally instead, with rows padded so the estimate still lands above the cap being asserted. Both assertions are unchanged, and the test no longer spends a download and ten retries getting there.
|
Claude finished @waralexrom's task in 2m 14s —— View job Re-review after
|
| # | Severity | Location | Issue |
|---|---|---|---|
| 1 | Low | mod.rs:4881–4891 | 5-line comment over 6 lines of code, whose second half restates the constants below it. Only the first sentence is load-bearing (estimate_rows stats but never reads). 256 is not arbitrary — it is exactly estimate_rows's average_row_length, so one padded row ≈ one estimated row — and 813 is what the count(*) assert pins; naming them would carry that better than prose. Commented inline. |
Note, not blocking
This commit is unrelated to the PR's subject. The title, description and the other two commits are all about websocket log levels; a flaky-test fix riding along is easy to miss in review and in git log --oneline for the log-level change. Worth a line in the PR description, or splitting it out — your call, and I'd not hold the PR for it.
Also still open from the previous round, unchanged and outside this diff: mod.rs:700 and mod.rs:783 log a dropped per-connection mpsc receiver at error, which is the same class of disconnect noise this PR targets. Follow-up material if the error rate is still above threshold after this ships.
Not verified
I could not run cargo test -p cubestore table_partition_split_threshold, cargo check or cargo fmt --check — all need approval in this environment. The row-size arithmetic above is by hand from the literals in the diff. Worth confirming the cubestore CI job is green.
| // The threshold is derived from the size of the location, | ||
| // not from its contents: see ImportServiceImpl::estimate_rows. | ||
| // Rows are padded so the estimate lands above | ||
| // max_partition_split_threshold per select worker, which is | ||
| // what makes the cap observable. | ||
| let path = env::temp_dir().join(format!("{}.csv", test_name)); | ||
| let padding = "x".repeat(256); | ||
| let mut csv = "Response ID,Start Date,End Date\n".to_string(); | ||
| for id in 0..813 { | ||
| csv += &format!("{},2020-01-01T00:00:00.000Z,{}\n", id, padding); | ||
| } |
There was a problem hiding this comment.
The generated file is the right call, and the arithmetic checks out (232,440 bytes → 907 estimated rows → 453 per select worker, comfortably above the 200 cap). Two small things about how that arithmetic is expressed:
The comment is 5 lines for 6 lines of code, and its second half restates what the constants below already do. The load-bearing fact is the first sentence — estimate_rows never opens the file, only stats it — because that is what makes a synthetic file valid here at all. The rest would read better as names on the numbers: 256 is not an arbitrary pad width, it is exactly estimate_rows's average_row_length, so one padded row ≈ one estimated row, and 813 is the row count the count(*) assert below pins. Something like:
// estimate_rows only stats the location, it never reads it.
let rows = 813;
// One padded row is about one estimated row: estimate_rows divides by 256.
let padding = "x".repeat(256);makes the "813 rows / 2 workers > 200" chain visible without prose. Not blocking either way.
The test imported a CSV over HTTP from a third-party host, which refuses the download, so the table never became ready and the test ran into the harness timeout. This is the only test covering the HTTP import path, so the location has to stay a URL rather than become a local file. Serve the CSV from a listener the test owns, as the TODO the test carried asked for. The body is held back for a moment because the test asserts that a concurrent query cannot see a table whose import is still running, and a local download would otherwise finish before the query is planned.
The test restated the match arms of the classification it covered, so it could only ever fail by being edited alongside them.
|
Claude finished @waralexrom's task in 3m 22s —— View job Re-review after
|
| # | Severity | Location | Issue |
|---|---|---|---|
| 1 | Low | files.rs:92, 96 | while let Ok(..) ends the accept loop on the first transient accept error, turning the server into a black hole that surfaces as an import timeout rather than a server failure; and log::error! fires on a benign in-flight disconnect after Drop, which is the same noise class this PR is about. Commented inline. |
| 2 | Low | tests.rs:2479 | The 500 ms download_delay is an unnamed timing window; a oneshot fired from the SELECT branch of the join! would make the "import still running" precondition deterministic. Commented inline. |
Note on 880d836
The rationale holds up as far as it goes — the assertions did mirror the match arms one-for-one, and that shape of test can't catch a semantic change in tungstenite itself, only an edit to our own match. But an edit to our own match is the realistic regression: a later refactor that reorders the two Protocol(..) arms, folds Io back into a single arm, or drops AlreadyClosed now lands silently, and the PR description argues for listing ConnectionClosed/AlreadyClosed defensively precisely because a future version bump might route through them. Deleting the only executable statement of that intent is a real, if small, loss for a test that cost nothing to run. Your call — I'd keep it, and I wouldn't hold the PR over it.
Related housekeeping: the PR description's Testing section still cites http::tests::websocket_error_levels as covering the classification, and doesn't mention either of the two flaky-test fixes now riding along. Worth a refresh before merge so the description matches what is being merged.
Still open, unchanged
- The
sql/mod.rs:4891comment/magic-numbers thread from the previous round still applies to the current code — left unresolved, not re-posted. - Outside this diff:
http/mod.rs:700andhttp/mod.rs:783still log a dropped per-connectionmpscreceiver aterror, the same disconnect-noise class this PR targets. Follow-up material.
Not verified
cargo fmt --check, cargo check and cargo test -p cubestore-sql-tests create_table_with_url all require approval in this environment, so the review is by reading. Two things I'd want CI to confirm: that no import in http/mod.rs's tests module went unused when websocket_error_levels was deleted, and that the cubestore SQL-test job passes with the new server.
| // The body is held back because the query below has to run against a table | ||
| // whose import has not finished: only ready tables are visible to the | ||
| // planner. | ||
| let server = serve_file(csv, Duration::from_millis(500)).await?; |
There was a problem hiding this comment.
Serving the file ourselves is the right fix, and the assertion is more robust than it looks — if the SELECT is planned before CREATE TABLE registers the table it fails with "not found" rather than "not ready", so either ordering satisfies is_err(). The one way it can flip is the SELECT future not being polled to completion within the 500 ms window on a loaded runner, at which point the import has finished and the table is queryable.
500 ms is probably enough in practice, but the window is a magic number that only the prose above explains. Releasing the body on a signal instead would remove the timing dependency entirely — have serve_file take a oneshot::Receiver, and fire the sender in the SELECT branch of the join! once the query has returned. Failing that, a named constant would at least say what the number is protecting.
Not blocking — the failure mode is a re-run, not a wrong result.
| let body = body.clone(); | ||
| tokio::spawn(async move { | ||
| if let Err(e) = serve_one_request(socket, &body, download_delay).await { | ||
| log::error!("Test file server: {}", e); |
There was a problem hiding this comment.
Two small things about the accept loop, neither blocking:
log::error!here fires on a benign disconnect too —Dropaborts only the accept task, so an in-flightserve_one_requestwhose peer went away (the test finished, the importer dropped the connection after a retry) writes to a closed socket and logs anerror. Given what this PR is about,debug!seems more consistent; nothing an operator or a CI reader can act on.while let Ok(..)exits the loop on the firstaccepterror, so a transient failure silently turns the server into a black hole and the test then fails as an import timeout rather than as "the server stopped".Err→continue(or abreakwith a log) would make that legible.
2 participants
Summary
A websocket client that disconnects without a close handshake was logged as an
error, even though that is how connections normally end: the Cube Store driver
terminates them by design on a heartbeat timeout, on a write error and on
dispose, and a killed process or a closed browser tab looks the same from the
server. A rolling restart of the API therefore produced one error line per
connection and pushed the error rate of a perfectly healthy node over its
alerting threshold. This classifies the read-stream error instead of reporting
every one of them at
error.Changes
websocket_error_level()/tungstenite_error_level()inhttp/mod.rspickthe level for an error from the websocket read stream; the call site logs
through
log::log!with the level they return.debug: a peer that is simply gone —Protocol(ResetWithoutClosingHandshake),Iowith kindConnectionReset,ConnectionAborted,BrokenPipe,NotConnectedorUnexpectedEof, plusConnectionClosed/AlreadyClosed. The last two cannot reach this branchwith the current
tokio-tungstenite, which turns them into the end of thestream, but they are a normal close either way and are listed so a version
bump cannot turn a graceful close into an error.
warn:Protocol(ReceivedAfterClosing)— a frame that raced the peer's ownclose frame. Harmless for the connection, worth seeing if a client does it
often.
error, unchanged: every other protocol violation (InvalidOpcode,NonZeroReservedBits,ControlFrameTooBig, ...),Tls,Capacity,Utf8,AttackAttempt,WriteBufferFull, and anyIoerror whose kind is not avanished peer.
Iois split by kind rather than lowered as a group, so agenuine failure of the connection is still reported as one.
Testing
http::tests::websocket_error_levelscovers one representative per class,including both shapes a vanished peer arrives in and an
Ioerror that muststay at
error. The classification is a function overtungstenite::Errorrather than
warp::Errorprecisely so it is constructible in a test —warp::Errorhas no public constructor.cargo check -p cubestore --lib --all-targetsclean,cargo fmtapplied.