fix: analyze a query once per execution, not once per attempt (#67)

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 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.
 
 **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.

CHANGELOG.md

@@ -11,6 +11,39 @@ 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.
+- **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
   an absent row source, and the parser refilled `InsertColumnsListed` from
@@ -61,6 +94,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

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,48 +215,46 @@ 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
 		values, verr := namedToValues(args)
 		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
 		values, verr := namedToValues(args)
 		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
@@ -310,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,6 +384,43 @@ 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
+// 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.
+//
+// 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 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 (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) || errors.Is(err, driver.ErrBadConn) {
+		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) {