fix: improve log slow/error SQL with args and accurate streaming durations#306
Merged
Merged
Conversation
The logged duration_ms for SELECT statements was the time it took db.QueryContext to return the *sql.Rows handle — typically sub-millisecond — not the wall-clock time spent inside rows.Next. That made every streaming query look instantaneous in the log even when its scan took hundreds of milliseconds, and made the slow-query threshold useless for queries that stream large result sets or materialize correlated subqueries lazily. Wrap *sql.Rows in *loggedRows. Close emits a single "sql" log line whose duration_ms reflects total elapsed time since Query returned. Close is idempotent so the common defer-then-close pattern only emits one line. Errors at Query are still logged immediately because no rows handle is returned to scan. chunkQuerier and the three func(*sql.Rows) callbacks in messages.go, plus scanMessageRows in api.go and the *sql.Rows declaration in ListSources, switch to *loggedRows. The wrapper embeds *sql.Rows so every method outside Close is forwarded transparently.
Two changes that make the SQL log useful when something is wrong: Args on WARN paths. logStmt and logStmtWith now take []any instead of int and attach an "args" attr only on slow + error lines. Without bound parameter values, a slow or failing query that hits a templated statement is unreproducible — every line looks identical except for the run-id. Args are not attached on Info/Debug or --full-trace lines: those run for every successful query, the args carry PII (subjects, addresses, IDs), and nargs is sufficient at that volume. formatArgs renders strings with a 64-char cap, raw byte slices as <N bytes>, and other Go values through %v. Head+tail truncation. normalizeStmt previously cut at the first N chars; for the dedup group-fetch query (and other long-tailed SELECTs with discriminating WHERE clauses), this systematically hid the part of the statement that distinguishes one logged query from another. The new form keeps roughly the first 60% and last 40% of the budget joined by " ... ", so WHERE, GROUP BY, and ORDER BY clauses survive. Tiny budgets still fall back to head-only truncation.
…ne logStmt Three fixes from review job 429: Check r.closed before calling r.Rows.Close so the embedded Close is never invoked twice on repeated Close calls. Cap string args at 64 runes rather than 64 bytes in formatArgs, avoiding a mid-rune cut on multi-byte UTF-8 (CJK subjects, emoji). Remove the logStmt passthrough; all call sites now call logStmtWith directly.
jesserobbins
changed the title
roborev: Combined Review (
|
… stmt truncation Three fixes addressing roborev mediums on PR wesm#306 (commit 20a2bd3): - Replace formatArgs with formatArgsShape on slow/error log paths. Bound parameters now log as `args_shape=[int64 string(len=12) bytes(len=11) nil]` instead of raw values, so subjects, addresses, tokens, and body excerpts cannot land in logs. Type and length are enough to diagnose a slow or failing query (placeholder count, NULL bind in the wrong slot, an unexpectedly huge string) without persisting sensitive content. - loggedRows.Close now consults Rows.Err() when Close itself returns nil, so context cancellation and driver-level scan failures discovered during rows.Next() get logged as "sql error" rather than as a successful query. - normalizeStmt truncates by rune count, not byte count. SQL literals or comments containing multi-byte UTF-8 (café, 漢) no longer split mid-rune and emit invalid UTF-8 to logs. Fast-path threshold uses utf8.RuneCountInString; the head+tail and tiny-budget branches both slice through []rune. Tests: - TestLogStmt_SlowQueryIncludesArgsShape — asserts type/length present, raw values absent, legacy "args" attr absent. - TestFormatArgsShape_RedactsValues — direct check across string, []byte, nil, numeric. - TestLoggedRows_IterationErrorSurfacedOnClose — cancels context mid-scan and asserts "sql error" line is emitted on Close. - TestNormalizeStmt_UTF8Safe — utf8.ValidString on both head+tail and tiny-budget paths.
roborev: Combined Review (
|
…lose
duration_ms for a streaming query previously reflected wall-clock time
between db.Query return and the caller's deferred rows.Close. For the
common pattern
rows, _ := db.Query(...)
defer rows.Close()
for rows.Next() { ... }
// unrelated work: count queries, batchPopulate, post-processing
the recorded duration absorbed the unrelated post-iteration work, making
slow-query logs misattribute time.
Move the timing finalizer to the end of iteration. loggedRows now
overrides Next as well as Close. Both paths route through an idempotent
finalize() that emits the log line exactly once:
- Next finalizes when the embedded Rows.Next() returns false
(normal end-of-scan). The deferred Close still fires; finalize
short-circuits on the second call.
- Close finalizes for the early-exit path where the caller breaks
out of the loop without exhausting rows.
Both paths consult Rows.Err() when no close error is present, so context
cancellation and driver-level scan failures continue to surface as
"sql error" lines.
Tests:
- TestLoggedRows_FinalizesAtEndOfScan — sleeps 50ms after the loop
and asserts duration_ms is captured before the sleep and not
re-emitted on Close.
- TestLoggedRows_EarlyExitFinalizesOnClose — breaks after one row
and asserts the log line lands on Close, exactly once.
roborev: Combined Review (
|
jesserobbins
changed the title
Owner
|
LGTM! Thank you |
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
2 participants
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.
Motivation
(Deliberately not affected by & mergable with #304) This PR enhances #263 by sharpening the SQL logger so slow and failing queries actually tell you what happened. Three things change. First, streaming queries now record their duration at
rows.Closeinstead of whendb.Queryreturns, because the work happens while you read rows, not when you get the handle. Second, slow and errored queries log their bound args, and the statement truncation preserves theWHEREclause, so you can see what ran with what values without the diagnostic part getting cut off. Third, a few small correctness fixes:loggedRows.Closeordering, UTF-8-safe arg truncation, andlogStmtinlined where it belongs.Summary
rows.Close, not atdb.QueryreturnWHEREclause when truncating long statementsloggedRows.Closeordering, make arg truncation UTF-8-safe, inlinelogStmt