From 577c8256a36bbdb5d2199b55ca89a5d5e696445e Mon Sep 17 00:00:00 2001 From: kartik Date: Fri, 25 Sep 2026 16:01:58 +0530 Subject: [PATCH 1/2] fix: analyze after the base answers so ErrSkip is not double-counted (#67) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit wConn.QueryContext/ExecContext analyzed the query before handing it to the base driver. A base with no direct Queryer/Execer was handled, but not one that has the entry point and declines an individual call with driver.ErrSkip: database/sql then falls back to Prepare+Query, which re-enters through wStmt and analyzes the same execution a second time. That is the common path, not an edge case — go-sql-driver/mysql returns ErrSkip for every parameterized query unless interpolateParams=true — so on MySQL essentially all traffic was analyzed twice. The duplicate static finding hid behind the default dedup window, but the N+1 counter is not deduped: every configured threshold was effectively halved. The base is now called first and analyzeExecuted skips analysis when the answer is ErrSkip, leaving the prepare path as the single analysis point. Findings are produced after execution on this path, which nothing consumes, and the latency window is read before the rules run so analysis time cannot push a query past the slow-query threshold. The fake ErrSkip driver in driver_fallback_test.go pins the behaviour (2 findings and a tripped N+1 threshold before the fix), alongside a direct-path driver proving bases that do execute are unaffected. --- AGENTS.md | 2 + CHANGELOG.md | 18 ++++ middleware/driver.go | 60 +++++++++---- middleware/driver_fallback_test.go | 135 +++++++++++++++++++++++++---- website/docs/middleware.md | 8 ++ 5 files changed, 189 insertions(+), 34 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 8cfe16a..1b4e037 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -41,6 +41,8 @@ When changing the public API or Go version, update all nine `go.mod` files and ` **Runtime interception is at the `database/sql` driver layer, not a wrapper type.** `middleware/driver.go` hand-implements the standard sqlmw/instrumentedsql/otelsql chain (`Driver`+`DriverContext` → `Connector` → `Conn` → `Stmt`/`Tx`) with zero dependencies. Consumers get a real `*sql.DB` back via `sqlguard.Register(name, baseDriver, opts...)` (then `sql.Open`) or `sqlguard.OpenDB(connector, opts...)`. Key invariant: optional driver interfaces (`QueryerContext`, `Pinger`, `SessionResetter`, `NamedValueChecker`, …) are _structurally_ implemented on every wrapper type, but each method forwards to the base only if the base implements that interface, otherwise returns `driver.ErrSkip` / a documented no-op so `database/sql` falls back exactly as it would for the bare driver. Do not "simplify" these away — they preserve base-driver behavior. The deprecated-path delegations (`base.Begin`, legacy `Queryer`/`Execer`, `Stmt.Exec/Query`) are deliberate and `//nolint:staticcheck`-annotated; a faithful wrapper must delegate to whatever the wrapped driver exposes. +**A query must be analyzed exactly once per execution, so `wConn.QueryContext`/`ExecContext` analyze _after_ calling the base, never before** (`analyzeExecuted`). `ErrSkip` is a per-call answer, not only a per-driver one: a base that implements `QueryerContext` may still decline an individual query with it, and `database/sql` then retries through Prepare+Query, which re-enters via `wStmt` and analyzes there. Analyzing before the base call therefore counts one logical query twice — and this is the common path, not an edge case, since `go-sql-driver/mysql` returns `ErrSkip` for every parameterized query unless `interpolateParams=true`. The duplicate static finding hides behind the dedup window; the doubled N+1 count does not, and halves every configured threshold (#67). `Guard.Observe` (check-then-time) is the right shape only where the interception point is told the query ran — the `wStmt` methods and the out-of-tree integrations — not on this path. Pinned by the `fakeErrSkipDriver` tests in `middleware/driver_fallback_test.go`. + **`middleware/guard.go`** is the single analysis core, exported as `middleware.Guard` with `Check` / `CheckLatency` / `Observe` (start-end split, returns a latency closure designed for ctx-stashed tracer hooks like pgx) / `ResetN1` / `Analyzer`. Every interception point in the driver chain (`driver.go`) calls into one `Guard`, and **every out-of-tree integration must too** — `integrations/pgxguard` is the reference example. Hand-rolling `check`/`checkLatency` (the old `sqlxguard`/`gormguard` pattern) silently loses redaction-by-default, fingerprints, the parser seam, config, and N+1; do not copy that shape for new integrations. **The analyzer is parser-pluggable.** `analyzer.Analyzer` runs `Rule`s against a normalized, dialect-agnostic `Statement` produced by an `analyzer.Parser` (`analyzer/parser.go`, `statement.go`). The default `FallbackParser` (`fallback.go`) is zero-dependency, strips comments/string literals, and never errors. `analyzer.Analyze` degrades to the FallbackParser if a configured parser errors, so analysis never breaks the caller's query path. Real grammars are supplied via `middleware.WithParser(...)` / `analyzer.Default().WithParser(...)` using the `parsers/*` modules. Rules read the `Statement`, never raw SQL. diff --git a/CHANGELOG.md b/CHANGELOG.md index 1f95152..3741531 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,23 @@ the same version in lockstep. ### Fixed +- **Every query is no longer analyzed twice when the base driver returns + `driver.ErrSkip`** ([#67]). `wConn.QueryContext`/`ExecContext` analyzed the + query before handing it to the base. A base with no direct `Queryer`/`Execer` + was covered, but not one that has the entry point and declines the call with + `driver.ErrSkip`: `database/sql` then falls back to Prepare+Query, which + re-enters through the wrapped statement and analyzes the same execution a + second time. `go-sql-driver/mysql` returns `ErrSkip` for every parameterized + query unless `interpolateParams=true`, which is off by default — so on MySQL + essentially all traffic was double-analyzed. **N+1 counts were doubled**, + halving the effective threshold (`WithN1Detection(10, …)` fired at 5 real + queries) and producing spurious N+1 reports; duplicate static findings were + masked by the default one-minute dedup window and only surfaced under + `WithFindingDedup(0)`. The base is now called first and analysis is skipped + when it answers `ErrSkip`, so the prepare path remains the single analysis + point. On this path findings are produced after execution rather than + before, which nothing consumes. + - **`pgparser` no longer reports `insert-without-columns` on `INSERT INTO t DEFAULT VALUES`** ([#68]). The grammar encodes that form as an absent row source, and the parser refilled `InsertColumnsListed` from @@ -61,6 +78,7 @@ the same version in lockstep. column list" to "Row-inserting statement without an explicit column list", since it no longer fires only on `INSERT`. +[#67]: https://github.com/KARTIKrocks/sqlguard/issues/67 [#68]: https://github.com/KARTIKrocks/sqlguard/issues/68 ## [0.4.0] - 2026-09-25 diff --git a/middleware/driver.go b/middleware/driver.go index 363a1a0..8d92e44 100644 --- a/middleware/driver.go +++ b/middleware/driver.go @@ -6,6 +6,7 @@ import ( "database/sql/driver" "errors" "fmt" + "time" ) // This file implements the standard database/sql driver-wrapping pattern @@ -214,15 +215,14 @@ func (c *wConn) BeginTx(ctx context.Context, opts driver.TxOptions) (driver.Tx, } func (c *wConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { - // Observe only on a path that actually executes. When the base has no direct - // Query entry point we return driver.ErrSkip *without* analyzing, so - // database/sql's Prepare+Query fallback — which re-enters through wStmt — is - // the single place this query is analyzed. Analyzing here too would count - // the same logical query twice (a duplicate finding and an inflated N+1). + // Analyze only on a path that actually executes — see analyzeExecuted for + // why that decision can only be made after calling the base. When the base + // has no direct Query entry point at all we return driver.ErrSkip without + // analyzing, for the same reason. if qc, ok := c.base.(driver.QueryerContext); ok { - done := c.g.Observe(query) + start := time.Now() rows, err := qc.QueryContext(ctx, query, args) - done(err) + analyzeExecuted(c.g, query, start, err) return rows, err } if q, ok := c.base.(driver.Queryer); ok { //nolint:staticcheck // legacy fallback @@ -230,22 +230,21 @@ func (c *wConn) QueryContext(ctx context.Context, query string, args []driver.Na if verr != nil { return nil, verr } - done := c.g.Observe(query) + start := time.Now() rows, err := q.Query(query, values) - done(err) + analyzeExecuted(c.g, query, start, err) return rows, err } return nil, driver.ErrSkip } func (c *wConn) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { - // See QueryContext: analyze only when this path executes. Returning ErrSkip - // without analyzing lets the Prepare+Exec fallback (via wStmt) be the single - // analysis point, avoiding a double count. + // See QueryContext: analyze only when this path executes, which is known + // only once the base has answered. if ec, ok := c.base.(driver.ExecerContext); ok { - done := c.g.Observe(query) + start := time.Now() res, err := ec.ExecContext(ctx, query, args) - done(err) + analyzeExecuted(c.g, query, start, err) return res, err } if e, ok := c.base.(driver.Execer); ok { //nolint:staticcheck // legacy fallback @@ -253,9 +252,9 @@ func (c *wConn) ExecContext(ctx context.Context, query string, args []driver.Nam if verr != nil { return nil, verr } - done := c.g.Observe(query) + start := time.Now() res, err := e.Exec(query, values) - done(err) + analyzeExecuted(c.g, query, start, err) return res, err } return nil, driver.ErrSkip @@ -376,6 +375,35 @@ func (t *wTx) Rollback() error { return t.base.Rollback() } // ---- helpers ---- +// analyzeExecuted analyzes a query the base driver has just been handed and +// records its latency. It is Guard.Observe split around the call, because on +// the conn-level Query/Exec path whether the query ran at all is known only +// from the base's answer: driver.ErrSkip means the base declined it, and +// database/sql then retries through Prepare+Query, which re-enters via wStmt. +// Analyzing here too would count one logical query twice — a duplicate +// finding and, worse, a doubled N+1 count, halving the configured threshold. +// +// This is the common path, not an edge case: go-sql-driver/mysql returns +// ErrSkip for every parameterized query unless interpolateParams=true, which +// is off by default. +// +// Analysis therefore happens after execution here rather than before it; +// nothing consumes findings pre-execution. Elapsed is read before Check so the +// measured latency stays the base driver's alone — running the rules inside +// the window would let analysis time push a query past the slow-query +// threshold. Latency is recorded only for a successful call, matching +// Guard.Observe (a failed query's latency is meaningless). +func analyzeExecuted(g *Guard, query string, start time.Time, err error) { + if errors.Is(err, driver.ErrSkip) { + return + } + elapsed := time.Since(start) + g.Check(query) + if err == nil { + g.CheckLatency(query, elapsed) + } +} + // namedToValues converts named values to positional values for the legacy // Queryer/Execer/Stmt fallback paths, which predate named parameters. func namedToValues(named []driver.NamedValue) ([]driver.Value, error) { diff --git a/middleware/driver_fallback_test.go b/middleware/driver_fallback_test.go index 071ee3b..0c646f7 100644 --- a/middleware/driver_fallback_test.go +++ b/middleware/driver_fallback_test.go @@ -1,6 +1,7 @@ package middleware import ( + "context" "database/sql" "database/sql/driver" "fmt" @@ -42,14 +43,52 @@ type fakeTx struct{} func (*fakeTx) Commit() error { return nil } func (*fakeTx) Rollback() error { return nil } -// openFakeGuarded registers a wrapped fakeNoQueryerDriver and returns the DB -// plus the reporter that records findings. Dedup is off so every analysis is -// counted (the bug would surface as 2 findings for one query). -func openFakeGuarded(t *testing.T) (*sql.DB, *countingReporter) { +// fakeErrSkipDriver mirrors go-sql-driver/mysql: its Conn *does* implement +// QueryerContext/ExecerContext, but declines every query with driver.ErrSkip +// (mysql does exactly that for parameterized queries unless +// interpolateParams=true, which is off by default). database/sql then falls +// back to Prepare+Query, re-entering through wStmt, so the query must still +// be analyzed exactly once. +type fakeErrSkipDriver struct{} + +func (fakeErrSkipDriver) Open(string) (driver.Conn, error) { return &errSkipConn{}, nil } + +type errSkipConn struct{ fakeConn } + +func (*errSkipConn) QueryContext(context.Context, string, []driver.NamedValue) (driver.Rows, error) { + return nil, driver.ErrSkip +} + +func (*errSkipConn) ExecContext(context.Context, string, []driver.NamedValue) (driver.Result, error) { + return nil, driver.ErrSkip +} + +// fakeQueryerDriver answers on the direct path: its Conn executes the query +// itself, so database/sql never falls back to Prepare. Analysis happens at +// that level instead — still exactly once. +type fakeQueryerDriver struct{} + +func (fakeQueryerDriver) Open(string) (driver.Conn, error) { return &queryerConn{}, nil } + +type queryerConn struct{ fakeConn } + +func (*queryerConn) QueryContext(context.Context, string, []driver.NamedValue) (driver.Rows, error) { + return &fakeRows{}, nil +} + +func (*queryerConn) ExecContext(context.Context, string, []driver.NamedValue) (driver.Result, error) { + return driver.RowsAffected(0), nil +} + +// openFakeGuarded registers base wrapped in a Guard and returns the DB plus +// the reporter that records findings. Dedup is off so every analysis is +// counted (a double analysis surfaces as 2 findings for one query). +func openFakeGuarded(t *testing.T, base driver.Driver, extra ...Option) (*sql.DB, *countingReporter) { t.Helper() rep := &countingReporter{} name := fmt.Sprintf("sqlguard-fake-%d", driverSeq.Add(1)) - sql.Register(name, WrapDriver(fakeNoQueryerDriver{}, WithReporter(rep), WithFindingDedup(0))) + opts := append([]Option{WithReporter(rep), WithFindingDedup(0)}, extra...) + sql.Register(name, WrapDriver(base, opts...)) db, err := sql.Open(name, "") if err != nil { t.Fatalf("open: %v", err) @@ -59,7 +98,7 @@ func openFakeGuarded(t *testing.T) (*sql.DB, *countingReporter) { } func TestDriver_NoQueryerContextAnalyzedOnce(t *testing.T) { - db, rep := openFakeGuarded(t) + db, rep := openFakeGuarded(t, fakeNoQueryerDriver{}) rows, err := db.Query("DELETE FROM accounts") // flagged: delete-without-where if err != nil { @@ -73,7 +112,7 @@ func TestDriver_NoQueryerContextAnalyzedOnce(t *testing.T) { } func TestDriver_NoExecerContextAnalyzedOnce(t *testing.T) { - db, rep := openFakeGuarded(t) + db, rep := openFakeGuarded(t, fakeNoQueryerDriver{}) if _, err := db.Exec("DELETE FROM accounts"); err != nil { t.Fatalf("exec: %v", err) @@ -84,21 +123,81 @@ func TestDriver_NoExecerContextAnalyzedOnce(t *testing.T) { } } -// With N+1 enabled, each logical query must increment the counter once. If the -// ErrSkip path double-counted, threshold=2 would trip after a single query. +// With N+1 enabled, each logical query must increment the counter once. If a +// fallback path double-counted, threshold=2 would trip after a single query. func TestDriver_NoQueryerContextN1CountedOnce(t *testing.T) { - rep := &countingReporter{} - name := fmt.Sprintf("sqlguard-fake-%d", driverSeq.Add(1)) - sql.Register(name, WrapDriver(fakeNoQueryerDriver{}, - WithReporter(rep), WithFindingDedup(0), WithN1Detection(2, time.Minute))) - db, err := sql.Open(name, "") + assertOneQueryDoesNotTripN1(t, fakeNoQueryerDriver{}) +} + +// The ErrSkip path is the one that matters in production: on MySQL every +// parameterized query takes it, so a double count halves every configured +// N+1 threshold (issue #67). +func TestDriver_ErrSkipQueryAnalyzedOnce(t *testing.T) { + db, rep := openFakeGuarded(t, fakeErrSkipDriver{}) + + rows, err := db.Query("DELETE FROM accounts") // flagged: delete-without-where if err != nil { - t.Fatalf("open: %v", err) + t.Fatalf("query: %v", err) + } + rows.Close() + + if got := rep.count(); got != 1 { + t.Errorf("a query the base declined with ErrSkip must be analyzed once, got %d", got) + } +} + +func TestDriver_ErrSkipExecAnalyzedOnce(t *testing.T) { + db, rep := openFakeGuarded(t, fakeErrSkipDriver{}) + + if _, err := db.Exec("DELETE FROM accounts"); err != nil { + t.Fatalf("exec: %v", err) + } + + if got := rep.count(); got != 1 { + t.Errorf("an exec the base declined with ErrSkip must be analyzed once, got %d", got) + } +} + +func TestDriver_ErrSkipN1CountedOnce(t *testing.T) { + assertOneQueryDoesNotTripN1(t, fakeErrSkipDriver{}) +} + +// A base that does handle the direct path is unaffected: it executes the +// query itself, database/sql never falls back, and the single analysis +// happens at the conn level. +func TestDriver_DirectQueryerAnalyzedOnce(t *testing.T) { + db, rep := openFakeGuarded(t, fakeQueryerDriver{}) + + rows, err := db.Query("DELETE FROM accounts") // flagged: delete-without-where + if err != nil { + t.Fatalf("query: %v", err) } - defer db.Close() + rows.Close() + + if got := rep.count(); got != 1 { + t.Errorf("a query the base executed directly must be analyzed once, got %d", got) + } + + if _, err := db.Exec("DELETE FROM accounts"); err != nil { + t.Fatalf("exec: %v", err) + } + + if got := rep.count(); got != 2 { + t.Errorf("the direct exec path must add exactly one analysis, got %d total", got) + } +} + +func TestDriver_DirectQueryerN1CountedOnce(t *testing.T) { + assertOneQueryDoesNotTripN1(t, fakeQueryerDriver{}) +} + +// assertOneQueryDoesNotTripN1 runs a single non-flagged query against base +// with the N+1 threshold at 2: nothing may be reported, because one execution +// must move the counter by one. +func assertOneQueryDoesNotTripN1(t *testing.T, base driver.Driver) { + t.Helper() + db, rep := openFakeGuarded(t, base, WithN1Detection(2, time.Minute)) - // One execution of a non-flagged query: no static finding, and the N+1 - // counter should be at 1 (below threshold 2), so nothing is reported. rows, err := db.Query("SELECT id, name FROM users WHERE id = ?", 1) if err != nil { t.Fatalf("query: %v", err) diff --git a/website/docs/middleware.md b/website/docs/middleware.md index 2fa7fb7..04aeca9 100644 --- a/website/docs/middleware.md +++ b/website/docs/middleware.md @@ -97,6 +97,14 @@ back exactly as it would for the bare driver. A driver that lacks `QueryerContext`, for example, still gets analyzed exactly once, on the prepare-then-execute path `database/sql` takes instead. +_Changed in 0.5._ The same holds for a driver that _has_ `QueryerContext` and +declines an individual query with `driver.ErrSkip` — `go-sql-driver/mysql` +does this for every parameterized query unless `interpolateParams=true`. +Before 0.5 that query was analyzed twice: once before the base declined, once +on the fallback path. N+1 counts were doubled on MySQL as a result. Analysis +on the direct path now happens once the base has answered, so a declined query +is analyzed only where it actually runs. + The wrapper never modifies the SQL text or the arguments. It observes. ## Reporters From e038c5d78ee3772fc287c5894f0d29fd6e4903e9 Mon Sep 17 00:00:00 2001 From: kartik Date: Fri, 25 Sep 2026 16:10:00 +0530 Subject: [PATCH 2/2] fix: skip analysis for ErrBadConn attempts and rejected stmt args MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review follow-up on the #67 fix: ErrSkip was not the only per-call answer that means "this did not execute". database/sql retries a query on driver.ErrBadConn — twice from the pool, then once on a brand-new connection — and every attempt re-enters the wrapper. One logical query was therefore analyzed up to three times, at the conn and the stmt level alike, which is the same N+1 inflation #67 fixed and shows up whenever pooled connections go stale (MySQL's wait_timeout, a restart, a failover). ErrBadConn's contract forbids returning it when the operation may have been performed, so a declined attempt ran nothing and analyzeExecuted now skips it. wStmt likewise analyzed before converting named parameters for a base that predates them, so a call failing with "driver does not support named parameters" — without reaching the database — still produced findings and bumped the N+1 counter. Conversion now runs first, and the statement paths use analyzeExecuted like the conn paths, so Guard.Observe is left to the out-of-tree integrations, which are only told a query ran. Three fake-driver tests pin it; against the previous commit they report 3 analyses for one retried query, a tripped N+1 threshold, and 1 analysis for a query that never ran. --- AGENTS.md | 2 +- CHANGELOG.md | 16 +++++ middleware/driver.go | 65 +++++++++++++-------- middleware/driver_fallback_test.go | 93 ++++++++++++++++++++++++++++++ website/docs/middleware.md | 6 +- 5 files changed, 155 insertions(+), 27 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 1b4e037..971e4ba 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -41,7 +41,7 @@ When changing the public API or Go version, update all nine `go.mod` files and ` **Runtime interception is at the `database/sql` driver layer, not a wrapper type.** `middleware/driver.go` hand-implements the standard sqlmw/instrumentedsql/otelsql chain (`Driver`+`DriverContext` → `Connector` → `Conn` → `Stmt`/`Tx`) with zero dependencies. Consumers get a real `*sql.DB` back via `sqlguard.Register(name, baseDriver, opts...)` (then `sql.Open`) or `sqlguard.OpenDB(connector, opts...)`. Key invariant: optional driver interfaces (`QueryerContext`, `Pinger`, `SessionResetter`, `NamedValueChecker`, …) are _structurally_ implemented on every wrapper type, but each method forwards to the base only if the base implements that interface, otherwise returns `driver.ErrSkip` / a documented no-op so `database/sql` falls back exactly as it would for the bare driver. Do not "simplify" these away — they preserve base-driver behavior. The deprecated-path delegations (`base.Begin`, legacy `Queryer`/`Execer`, `Stmt.Exec/Query`) are deliberate and `//nolint:staticcheck`-annotated; a faithful wrapper must delegate to whatever the wrapped driver exposes. -**A query must be analyzed exactly once per execution, so `wConn.QueryContext`/`ExecContext` analyze _after_ calling the base, never before** (`analyzeExecuted`). `ErrSkip` is a per-call answer, not only a per-driver one: a base that implements `QueryerContext` may still decline an individual query with it, and `database/sql` then retries through Prepare+Query, which re-enters via `wStmt` and analyzes there. Analyzing before the base call therefore counts one logical query twice — and this is the common path, not an edge case, since `go-sql-driver/mysql` returns `ErrSkip` for every parameterized query unless `interpolateParams=true`. The duplicate static finding hides behind the dedup window; the doubled N+1 count does not, and halves every configured threshold (#67). `Guard.Observe` (check-then-time) is the right shape only where the interception point is told the query ran — the `wStmt` methods and the out-of-tree integrations — not on this path. Pinned by the `fakeErrSkipDriver` tests in `middleware/driver_fallback_test.go`. +**A query must be analyzed exactly once per execution, so every interception point in `driver.go` analyzes _after_ calling the base, never before** (`analyzeExecuted`). Whether the base ran the query is knowable only from its answer, and two answers mean it did not — after each, `database/sql` re-issues the same logical query and it re-enters the chain. `driver.ErrSkip` is a per-call answer, not only a per-driver one: a base that implements `QueryerContext` may still decline an individual query, and the Prepare+Query fallback then analyzes it at `wStmt`; this is the common path, not an edge case, since `go-sql-driver/mysql` returns `ErrSkip` for every parameterized query unless `interpolateParams=true`. `driver.ErrBadConn` means the connection was already dead — its contract forbids returning it when the operation may have run — and `database/sql` retries the whole query up to twice more, at both the conn and the stmt level. Analyzing a declined attempt multiplies one logical query by two or three; the duplicate static finding hides behind the dedup window, but the inflated N+1 count does not and silently lowers every configured threshold (#67). Argument conversion (`namedToValues`) therefore also runs _before_ analysis: a call it rejects never reaches the base. `Guard.Observe` (check-then-time) stays for interception points that are only told a query ran, which is every out-of-tree integration (`pgxguard`'s tracer hooks, …); nothing in `driver.go` is in that position. Pinned by the `fakeErrSkipDriver` / `fakeBadConnDriver` tests in `middleware/driver_fallback_test.go`. **`middleware/guard.go`** is the single analysis core, exported as `middleware.Guard` with `Check` / `CheckLatency` / `Observe` (start-end split, returns a latency closure designed for ctx-stashed tracer hooks like pgx) / `ResetN1` / `Analyzer`. Every interception point in the driver chain (`driver.go`) calls into one `Guard`, and **every out-of-tree integration must too** — `integrations/pgxguard` is the reference example. Hand-rolling `check`/`checkLatency` (the old `sqlxguard`/`gormguard` pattern) silently loses redaction-by-default, fingerprints, the parser seam, config, and N+1; do not copy that shape for new integrations. diff --git a/CHANGELOG.md b/CHANGELOG.md index 3741531..2901777 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,22 @@ the same version in lockstep. when it answers `ErrSkip`, so the prepare path remains the single analysis point. On this path findings are produced after execution rather than before, which nothing consumes. +- **A query retried after `driver.ErrBadConn` is no longer analyzed once per + attempt.** `database/sql` retries a failed query on another connection — + twice from the pool, then once on a fresh connection — and every attempt + re-entered the wrapper, so one logical query could be analyzed three times. + `ErrBadConn`'s contract is that a driver must not return it when the + operation may have been performed, so a declined attempt executed nothing + and is now skipped, at the connection and the statement level alike. This is + the same N+1 inflation as [#67] from the other per-call "did not run" + answer, and it surfaces whenever pooled connections go stale: MySQL's + `wait_timeout`, a server restart, a failover. +- **A statement call rejected by argument conversion is no longer analyzed.** + `wStmt.ExecContext`/`QueryContext` ran the rules before converting named + parameters for a base that predates them, so a call that failed with + `sqlguard: driver does not support named parameters` — without ever + reaching the database — still produced findings and incremented the N+1 + counter. - **`pgparser` no longer reports `insert-without-columns` on `INSERT INTO t DEFAULT VALUES`** ([#68]). The grammar encodes that form as diff --git a/middleware/driver.go b/middleware/driver.go index 8d92e44..8989160 100644 --- a/middleware/driver.go +++ b/middleware/driver.go @@ -309,49 +309,58 @@ var ( func (s *wStmt) Close() error { return s.base.Close() } func (s *wStmt) NumInput() int { return s.base.NumInput() } +// The statement paths analyze after the base answers for the same reason the +// conn paths do (see analyzeExecuted). database/sql has no ErrSkip fallback +// here, but it does retry a statement on driver.ErrBadConn, so a stale +// connection would otherwise multiply the analysis count. Argument conversion +// happens first, so a call rejected before it reaches the base is never +// analyzed: it does not execute. + func (s *wStmt) Exec(args []driver.Value) (driver.Result, error) { - done := s.g.Observe(s.query) + start := time.Now() res, err := s.base.Exec(args) //nolint:staticcheck // delegated deprecated path - done(err) + analyzeExecuted(s.g, s.query, start, err) return res, err } func (s *wStmt) Query(args []driver.Value) (driver.Rows, error) { - done := s.g.Observe(s.query) + start := time.Now() rows, err := s.base.Query(args) //nolint:staticcheck // delegated deprecated path - done(err) + analyzeExecuted(s.g, s.query, start, err) return rows, err } func (s *wStmt) ExecContext(ctx context.Context, args []driver.NamedValue) (driver.Result, error) { - done := s.g.Observe(s.query) if ec, ok := s.base.(driver.StmtExecContext); ok { + start := time.Now() res, err := ec.ExecContext(ctx, args) - done(err) + analyzeExecuted(s.g, s.query, start, err) return res, err } values, verr := namedToValues(args) if verr != nil { return nil, verr } + start := time.Now() res, err := s.base.Exec(values) //nolint:staticcheck // legacy fallback - done(err) + analyzeExecuted(s.g, s.query, start, err) return res, err } func (s *wStmt) QueryContext(ctx context.Context, args []driver.NamedValue) (driver.Rows, error) { - done := s.g.Observe(s.query) if qc, ok := s.base.(driver.StmtQueryContext); ok { + start := time.Now() rows, err := qc.QueryContext(ctx, args) - done(err) + analyzeExecuted(s.g, s.query, start, err) return rows, err } values, verr := namedToValues(args) if verr != nil { return nil, verr } + start := time.Now() rows, err := s.base.Query(values) //nolint:staticcheck // legacy fallback - done(err) + analyzeExecuted(s.g, s.query, start, err) return rows, err } @@ -376,25 +385,33 @@ func (t *wTx) Rollback() error { return t.base.Rollback() } // ---- helpers ---- // analyzeExecuted analyzes a query the base driver has just been handed and -// records its latency. It is Guard.Observe split around the call, because on -// the conn-level Query/Exec path whether the query ran at all is known only -// from the base's answer: driver.ErrSkip means the base declined it, and -// database/sql then retries through Prepare+Query, which re-enters via wStmt. -// Analyzing here too would count one logical query twice — a duplicate -// finding and, worse, a doubled N+1 count, halving the configured threshold. +// records its latency. It is Guard.Observe split around the call, because +// whether the query ran at all is known only from the base's answer. Two +// answers mean it did not run, and after both database/sql re-issues the same +// logical query, which re-enters this chain: +// +// - driver.ErrSkip — the base declined a direct Query/Exec, and database/sql +// falls back to Prepare+Query, re-entering through wStmt. This is the +// common path, not an edge case: go-sql-driver/mysql returns ErrSkip for +// every parameterized query unless interpolateParams=true, which is off by +// default. +// - driver.ErrBadConn — the connection was already dead. Its contract is +// that a driver must not return it if the operation may have been +// performed, so nothing executed; database/sql then retries the whole +// query on another connection, up to twice more. // -// This is the common path, not an edge case: go-sql-driver/mysql returns -// ErrSkip for every parameterized query unless interpolateParams=true, which -// is off by default. +// Analyzing either answer counts one logical query two or three times — a +// duplicate finding and, worse, a multiplied N+1 count that silently lowers +// the configured threshold. // -// Analysis therefore happens after execution here rather than before it; -// nothing consumes findings pre-execution. Elapsed is read before Check so the +// Analysis therefore happens after execution rather than before it; nothing +// consumes findings pre-execution. Elapsed is read before Check so the // measured latency stays the base driver's alone — running the rules inside // the window would let analysis time push a query past the slow-query -// threshold. Latency is recorded only for a successful call, matching -// Guard.Observe (a failed query's latency is meaningless). +// threshold. Latency is recorded only for a successful call (a failed query's +// latency is meaningless), matching Guard.Observe. func analyzeExecuted(g *Guard, query string, start time.Time, err error) { - if errors.Is(err, driver.ErrSkip) { + if errors.Is(err, driver.ErrSkip) || errors.Is(err, driver.ErrBadConn) { return } elapsed := time.Since(start) diff --git a/middleware/driver_fallback_test.go b/middleware/driver_fallback_test.go index 0c646f7..1fb4d45 100644 --- a/middleware/driver_fallback_test.go +++ b/middleware/driver_fallback_test.go @@ -6,6 +6,8 @@ import ( "database/sql/driver" "fmt" "io" + "strings" + "sync/atomic" "testing" "time" ) @@ -80,6 +82,35 @@ func (*queryerConn) ExecContext(context.Context, string, []driver.NamedValue) (d return driver.RowsAffected(0), nil } +// fakeBadConnDriver fails the first two executions with driver.ErrBadConn, +// as a driver does when the pool hands out a connection the server has since +// closed (MySQL's wait_timeout, a restart, a failover). database/sql retries +// the whole query on a fresh connection, re-entering the wrapper — and by +// ErrBadConn's contract the declined attempts executed nothing, so they must +// not be analyzed. +type fakeBadConnDriver struct{ fails atomic.Int64 } + +func (d *fakeBadConnDriver) Open(string) (driver.Conn, error) { return &badConn{d: d}, nil } + +type badConn struct { + fakeConn + d *fakeBadConnDriver +} + +func (c *badConn) QueryContext(context.Context, string, []driver.NamedValue) (driver.Rows, error) { + if c.d.fails.Add(-1) >= 0 { + return nil, driver.ErrBadConn + } + return &fakeRows{}, nil +} + +func (c *badConn) ExecContext(context.Context, string, []driver.NamedValue) (driver.Result, error) { + if c.d.fails.Add(-1) >= 0 { + return nil, driver.ErrBadConn + } + return driver.RowsAffected(0), nil +} + // openFakeGuarded registers base wrapped in a Guard and returns the DB plus // the reporter that records findings. Dedup is off so every analysis is // counted (a double analysis surfaces as 2 findings for one query). @@ -191,6 +222,68 @@ func TestDriver_DirectQueryerN1CountedOnce(t *testing.T) { assertOneQueryDoesNotTripN1(t, fakeQueryerDriver{}) } +// database/sql retries a query on driver.ErrBadConn (twice on a pooled +// connection, then once on a brand-new one). Each retry re-enters the wrapper, +// so analyzing a declined attempt multiplies one logical query by up to three +// — the same N+1 inflation as #67, from the other per-call "did not run" +// answer. +func TestDriver_BadConnRetryAnalyzedOnce(t *testing.T) { + base := &fakeBadConnDriver{} + base.fails.Store(2) + db, rep := openFakeGuarded(t, base) + + rows, err := db.Query("DELETE FROM accounts") // flagged: delete-without-where + if err != nil { + t.Fatalf("query: %v", err) + } + rows.Close() + + if got := base.fails.Load(); got != -1 { + t.Fatalf("expected the base to be called three times (two declines, one success), got %d remaining", got) + } + if got := rep.count(); got != 1 { + t.Errorf("a query retried past ErrBadConn must be analyzed once, got %d", got) + } +} + +func TestDriver_BadConnRetryN1CountedOnce(t *testing.T) { + base := &fakeBadConnDriver{} + base.fails.Store(2) + db, rep := openFakeGuarded(t, base, WithN1Detection(2, time.Minute)) + + rows, err := db.Query("SELECT id, name FROM users WHERE id = ?", 1) + if err != nil { + t.Fatalf("query: %v", err) + } + rows.Close() + + if got := rep.count(); got != 0 { + t.Errorf("one logical query must not trip N+1 (threshold 2) however often it was retried; got %d reports", got) + } +} + +// A statement whose arguments the legacy conversion rejects never reaches the +// base, so there is nothing to analyze: fakeStmt implements neither +// StmtQueryContext nor NamedValueChecker, and named parameters have no +// positional form. +func TestDriver_RejectedNamedArgsNotAnalyzed(t *testing.T) { + db, rep := openFakeGuarded(t, fakeNoQueryerDriver{}) + + // select-star would be reported if this were analyzed. + rows, err := db.Query("SELECT * FROM users WHERE id = :id", sql.Named("id", 1)) + if err == nil { + rows.Close() + t.Fatal("expected the named-parameter conversion to fail") + } + if !strings.Contains(err.Error(), "does not support named parameters") { + t.Fatalf("expected the wrapper's own conversion error, got %v", err) + } + + if got := rep.count(); got != 0 { + t.Errorf("a query rejected before it reached the base must not be analyzed, got %d", got) + } +} + // assertOneQueryDoesNotTripN1 runs a single non-flagged query against base // with the N+1 threshold at 2: nothing may be reported, because one execution // must move the counter by one. diff --git a/website/docs/middleware.md b/website/docs/middleware.md index 04aeca9..b86aae1 100644 --- a/website/docs/middleware.md +++ b/website/docs/middleware.md @@ -102,8 +102,10 @@ declines an individual query with `driver.ErrSkip` — `go-sql-driver/mysql` does this for every parameterized query unless `interpolateParams=true`. Before 0.5 that query was analyzed twice: once before the base declined, once on the fallback path. N+1 counts were doubled on MySQL as a result. Analysis -on the direct path now happens once the base has answered, so a declined query -is analyzed only where it actually runs. +now happens once the base has answered, so a declined query is analyzed only +where it actually runs. The same holds for `driver.ErrBadConn`, which +`database/sql` answers by retrying the query on another connection: the +attempt that hit the dead connection executed nothing, so it is not counted. The wrapper never modifies the SQL text or the arguments. It observes.