Fix all 14 verified bugs (8 reported + 6 from the hunt) with regression tests

cmd/pgbot/erd.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/pgrundev/pgbot/internal/conn"
 	"github.com/pgrundev/pgbot/internal/erd"
+	"github.com/pgrundev/pgbot/internal/model"
 	"github.com/spf13/cobra"
 )
 
@@ -41,7 +42,7 @@ func newERDCmd() *cobra.Command {
 			if err != nil {
 				return err
 			}
-			s.Info.Version = pgVersionShort(target.Caps.VersionNum)
+			s.Info.Version = model.PGVersionString(target.Caps.VersionNum)
 			switch {
 			case htmlOut:
 				fmt.Print(erd.RenderHTML(s))

cmd/pgbot/logs.go

@@ -82,6 +82,15 @@ func runLogs(cmd *cobra.Command, args []string, f logsFlags) error {
 		defer cancel()
 	}
 
+	// Capture the moment pgbot started connecting: its own "connection
+	// authenticated" lines (which name neither PID nor application_name, only
+	// the identity) can only be dropped when the entry is AT OR AFTER this
+	// moment. Entries before it are provably not pgbot's — they belong to other
+	// clients of the same role, and dropping them destroyed evidence.
+	// A small skew guard absorbs client-vs-server clock drift conservatively:
+	// if in doubt, KEEP the line (a false kept line is noise; a false drop is
+	// lost evidence).
+	selfSince := time.Now()
 	target, err := conn.Connect(ctx, connString)
 	if err != nil {
 		return err
@@ -103,7 +112,7 @@ func runLogs(cmd *cobra.Command, args []string, f logsFlags) error {
 		for _, pid := range target.SelfPIDs() {
 			own[int(pid)] = true
 		}
-		return !isSelfLogEntryForUser(e, own, connUser) && levels[e.Level]
+		return !isSelfLogEntryForUser(e, own, connUser, selfSince) && levels[e.Level]
 	}
 
 	src, err := pglog.NewSQLSource(ctx, target.Pool)
@@ -187,14 +196,27 @@ func isSelfLogEntry(e pglog.Entry, ownPIDs map[int]bool) bool {
 
 // isSelfLogEntryForUser additionally drops the authenticated-phase line for
 // pgbot's own role — the one connection line that names neither PID context
-// nor application_name, only the identity.
-func isSelfLogEntryForUser(e pglog.Entry, ownPIDs map[int]bool, user string) bool {
+// nor application_name, only the identity. It cannot be attributed precisely,
+// so it is dropped ONLY when the entry timestamp proves it can be pgbot's:
+// at/after pgbot's own session start (minus a clock-skew guard), when the
+// entry predates pgbot entirely it is another client's evidence and stays.
+func isSelfLogEntryForUser(e pglog.Entry, ownPIDs map[int]bool, user string, selfSince time.Time) bool {
 	if isSelfLogEntry(e, ownPIDs) {
 		return true
 	}
-	return user != "" &&
-		strings.HasPrefix(e.Message, "connection authenticated: ") &&
-		strings.Contains(e.Message, `identity="`+user+`"`)
+	if user == "" || selfSince.IsZero() {
+		return false // no identity / no session clock: never drop on a guess
+	}
+	if !strings.HasPrefix(e.Message, "connection authenticated: ") {
+		return false
+	}
+	if !strings.Contains(e.Message, `identity="`+user+`"`) {
+		return false
+	}
+	// Only entries comfortably after pgbot started can be its own; the guard
+	// errs toward KEEPING lines when the clocks disagree.
+	const skewGuard = 2 * time.Minute
+	return e.Time.After(selfSince.Add(skewGuard))
 }
 
 // queryLoggingNote explains an all-noise stream: with log_min_duration_statement

cmd/pgbot/logs_test.go

@@ -79,17 +79,39 @@ func TestIsSelfLogEntry(t *testing.T) {
 }
 
 // The authenticated-phase line carries only the role identity; pgbot's own
-// role authenticating is still pgbot's footprint.
+// role authenticating is still pgbot's footprint — but ONLY when the entry's
+// timestamp proves it can be pgbot's: entries predating pgbot's session (or
+// within the skew guard) are another client's evidence and must survive
+// (bug_report.md minor: the filter used to drop every client of the role).
 func TestIsSelfConnUser(t *testing.T) {
 	own := map[int]bool{}
-	e := pglog.Entry{Message: `connection authenticated: identity="pgbot_ro" method=scram-sha-256 (pg_hba.conf:128)`}
-	if !isSelfLogEntryForUser(e, own, "pgbot_ro") {
-		t.Error("own role's authenticated line must be filtered")
+	now := time.Now()
+	auth := func(at time.Time) pglog.Entry {
+		return pglog.Entry{Time: at, Message: `connection authenticated: identity="pgbot_ro" method=scram-sha-256 (pg_hba.conf:128)`}
 	}
-	if isSelfLogEntryForUser(e, own, "app") {
+	// pgbot's own line: comfortably after its session started (past the skew
+	// guard).
+	if !isSelfLogEntryForUser(auth(now.Add(5*time.Minute)), own, "pgbot_ro", now) {
+		t.Error("own role's authenticated line after session start must be filtered")
+	}
+	// Another role's line: kept regardless of time.
+	if isSelfLogEntryForUser(auth(now.Add(5*time.Minute)), own, "app", now) {
 		t.Error("another role's authenticated line must be kept")
 	}
-	if isSelfLogEntryForUser(pglog.Entry{Message: "some pgbot_ro mention elsewhere"}, own, "pgbot_ro") {
+	// Same role, but authenticated BEFORE pgbot started — another client's
+	// evidence: kept.
+	if isSelfLogEntryForUser(auth(now.Add(-time.Hour)), own, "pgbot_ro", now) {
+		t.Error("pre-session authenticated line must be kept — it is not pgbot's")
+	}
+	// Same role inside the skew guard — kept (when in doubt, keep evidence).
+	if isSelfLogEntryForUser(auth(now.Add(time.Minute)), own, "pgbot_ro", now.Add(10*time.Minute)) {
+		t.Error("entries inside the skew guard must be kept")
+	}
+	// Zero session clock: never drop on a guess.
+	if isSelfLogEntryForUser(auth(now.Add(time.Hour)), own, "pgbot_ro", time.Time{}) {
+		t.Error("without a session clock the line must be kept")
+	}
+	if isSelfLogEntryForUser(pglog.Entry{Time: now, Message: "some pgbot_ro mention elsewhere"}, own, "pgbot_ro", now) {
 		t.Error("only the authenticated-phase line matches, not any mention of the role")
 	}
 }

cmd/pgbot/queries.go

@@ -73,7 +73,7 @@ func runQueries(cmd *cobra.Command, args []string, f inspectFlags, byCalls bool)
 		label = "by call count"
 	}
 
-	fmt.Printf("%s · %s · top %d queries %s\n\n", st.Head(host), pgVersionShort(c.Server.VersionNum), len(top), st.Dim(label))
+	fmt.Printf("%s · %s · top %d queries %s\n\n", st.Head(host), c.Server.ShortVersion(), len(top), st.Dim(label))
 	tw := tabwriter.NewWriter(os.Stdout, 0, 2, 2, ' ', 0)
 	fmt.Fprintln(tw, "  total\tshare\tcalls\tmean\tquery")
 	for _, q := range top {

cmd/pgbot/tables.go

@@ -61,7 +61,7 @@ func runTables(cmd *cobra.Command, args []string, f inspectFlags) error {
 	if c.Tables.DBSizeBytes > 0 {
 		dbsize = " · " + render.HumanBytes(c.Tables.DBSizeBytes) + " database"
 	}
-	fmt.Printf("%s · %s · %s%s\n\n", st.Head(host), pgVersionShort(c.Server.VersionNum),
+	fmt.Printf("%s · %s · %s%s\n\n", st.Head(host), c.Server.ShortVersion(),
 		st.Dim(fmt.Sprintf("top %d tables by size", len(c.Tables.Top))), st.Dim(dbsize))
 
 	tw := tabwriter.NewWriter(os.Stdout, 0, 2, 2, ' ', 0)

cmd/pgbot/tune.go

@@ -60,7 +60,7 @@ func runTune(cmd *cobra.Command, args []string, f inspectFlags) error {
 		}
 	}
 
-	fmt.Printf("%s · %s · %d tuning recommendation(s)\n\n", st.Head(host), pgVersionShort(c.Server.VersionNum), len(tuning))
+	fmt.Printf("%s · %s · %d tuning recommendation(s)\n\n", st.Head(host), c.Server.ShortVersion(), len(tuning))
 	if busy, pool, ok := findings.PoolSizing(c); ok {
 		fmt.Printf("%s workload keeps ~%.1f backends busy on average → a server pool of ~%d connections (3× headroom) is the sizing starting point; max_connections is %d\n\n",
 			st.Dim("pool"), busy, pool, limitsMax(c))
@@ -84,10 +84,3 @@ func limitsMax(c *model.Context) int {
 	}
 	return c.Limits.ConnectionsMax
 }
-
-func pgVersionShort(num int) string {
-	if num == 0 {
-		return "postgres"
-	}
-	return fmt.Sprintf("postgres %d.%d", num/10000, num%100)
-}

cmd/pgbot/vacuum.go

@@ -87,7 +87,7 @@ func runVacuum(cmd *cobra.Command, args []string, f inspectFlags) error {
 	if behind > 0 {
 		summary = st.Warn(fmt.Sprintf("%d table(s) past the autovacuum threshold", behind))
 	}
-	fmt.Printf("%s · %s · %s\n\n", st.Head(host), pgVersionShort(c.Server.VersionNum), summary)
+	fmt.Printf("%s · %s · %s\n\n", st.Head(host), c.Server.ShortVersion(), summary)
 
 	tw := tabwriter.NewWriter(os.Stdout, 0, 2, 2, ' ', 0)
 	fmt.Fprintln(tw, "  table\tlive\tdead\tdead%\tlast autovacuum\tdue?")
@@ -150,15 +150,15 @@ func settingFloat(c *model.Context, name string, def float64) float64 {
 	return def
 }
 
-// agoStr renders how long ago a timestamp was, or "never" if unset.
+// agoStr renders how long ago a timestamp was, or "never" if unset. A future
+// timestamp (clock skew between pgbot and the server) reads as "just now" —
+// the same case d < time.Minute already covers, so there is no separate arm.
 func agoStr(t *time.Time) string {
 	if t == nil || t.IsZero() {
 		return "never"
 	}
 	d := time.Since(*t)
 	switch {
-	case d < 0:
-		return "just now"
 	case d < time.Minute:
 		return "just now"
 	case d < time.Hour:

cmd/pgbot/waits.go

@@ -185,7 +185,7 @@ func renderWaits(s *model.WaitStudy, group waitsGroup, target *conn.Target, f wa
 
 	for _, b := range s.Blockers {
 		fmt.Println(st.Head("Blocked → blocker (sustained evidence)"))
-		renderBlocker(st, b, s)
+		renderBlocker(st, b)
 	}
 	if len(s.Transient) > 0 {
 		fmt.Println(st.Dim(fmt.Sprintf("transient lock waits: %d holder(s) seen too briefly to name as a cause", len(s.Transient))))
@@ -258,11 +258,16 @@ func renderTopSessions(st render.Styler, s *model.WaitStudy) {
 	fmt.Println()
 }
 
-func renderBlocker(st render.Styler, b model.Blocker, s *model.WaitStudy) {
+func renderBlocker(st render.Styler, b model.Blocker) {
 	for _, v := range b.Victims {
 		fmt.Printf("  PID %d  %s\n", v.PID, truncStr(v.Query, 70))
-		if share := victimLockShareOf(s, v.PID); share > 0 {
-			fmt.Printf("    ~%.0f%% of its sampled time in Lock:%s\n", share*100, v.WaitEvent)
+		// LockShare is the victim's OWN sampled-time fraction (model 1.1.0):
+		// "~100% of its sampled time in Lock:relation" for a backend that was
+		// blocked every time it was seen. The old code printed the victim's share
+		// of the whole window here — 20% for a backend blocked in 40 of 200 window
+		// samples — mislabeled as "of its sampled time" (bug_report.md Bug 5).
+		if v.LockShare > 0 {
+			fmt.Printf("    ~%.0f%% of its sampled time in Lock:%s\n", v.LockShare*100, v.WaitEvent)
 		}
 	}
 	holder := fmt.Sprintf("blocked by PID %d (%s, xact age %.0fs", b.HolderPID, b.HolderState, b.HolderXactAgeS)
@@ -276,15 +281,6 @@ func renderBlocker(st render.Styler, b model.Blocker, s *model.WaitStudy) {
 	fmt.Println()
 }
 
-func victimLockShareOf(s *model.WaitStudy, pid int) float64 {
-	for _, sess := range s.Sessions {
-		if sess.PID == pid && sess.Count > 0 && strings.HasPrefix(sess.TopEvent, "Lock:") {
-			return sess.Share
-		}
-	}
-	return 0
-}
-
 // waitsConclusion is the evidence-gated bottom line. It never claims exact
 // timing, refuses to conclude from a thin sample, and never recommends an
 // index for lock contention — that is the entire point of the command.

cmd/pgbot/waits_test.go

@@ -1,13 +1,56 @@
 package main
 
 import (
+	"io"
+	"os"
 	"strings"
 	"testing"
 	"time"
 
 	"github.com/pgrundev/pgbot/internal/model"
+	"github.com/pgrundev/pgbot/internal/render"
 )
 
+// captureStdout runs fn with stdout redirected and returns what it printed.
+func captureStdout(t *testing.T, fn func()) string {
+	t.Helper()
+	old := os.Stdout
+	r, w, err := os.Pipe()
+	if err != nil {
+		t.Fatalf("pipe: %v", err)
+	}
+	os.Stdout = w
+	fn()
+	w.Close()
+	os.Stdout = old
+	out, _ := io.ReadAll(r)
+	return string(out)
+}
+
+// The blocker's victim line must print the victim's OWN sampled-time lock
+// fraction (model 1.1.0 LockShare), never its share of the whole window — a
+// backend blocked every time it was sampled reads ~100%, regardless of how
+// busy the rest of the database was (bug_report.md Bug 5).
+func TestRenderBlockerVictimShare(t *testing.T) {
+	b := model.Blocker{
+		HolderPID: 8172, HolderState: "idle in transaction", HolderXactAgeS: 43,
+		Observations: 5, Sustained: true,
+		Victims: []model.BlockedVictim{{
+			PID: 18442, WaitEvent: "transactionid", MaxWaitS: 12, LockShare: 1.0,
+			Query: "UPDATE orders SET status = 'paid' WHERE id = 42",
+		}},
+	}
+	out := captureStdout(t, func() { renderBlocker(render.NewStyler(false), b) })
+	if !strings.Contains(out, "~100% of its sampled time in Lock:transactionid") {
+		t.Errorf("victim line must print the per-victim lock share, got:\n%s", out)
+	}
+	b.Victims[0].LockShare = 0 // unattributed victim: no line, never a fabricated number
+	out = captureStdout(t, func() { renderBlocker(render.NewStyler(false), b) })
+	if strings.Contains(out, "of its sampled time") {
+		t.Errorf("a victim with no fast-plane samples must not get a share line:\n%s", out)
+	}
+}
+
 func TestClampWaits(t *testing.T) {
 	d, hz := clampWaits(10*time.Second, 10)
 	if d != 10*time.Second || hz != 10 {

internal/ai/bedrock.go

@@ -88,6 +88,15 @@ func bedrockModel(model, base, key string, httpc *http.Client) (LanguageModel, e
 		}
 	}
 	base = trimURL(base)
+	if httpc == nil {
+		httpc = &http.Client{Timeout: 3 * time.Minute}
+	}
+	// Never mutate the caller's client: Bedrock pins redirects off and may
+	// wrap the transport with its signer — on a shared client those changes
+	// would leak into every later call. A shallow copy is enough (only
+	// CheckRedirect and Transport are assigned below, both fields of the copy).
+	hc := *httpc
+	httpc = &hc
 	// Never forward a supplied or minted bearer token through a redirect.
 	httpc.CheckRedirect = func(*http.Request, []*http.Request) error { return http.ErrUseLastResponse }
 	if key == "" {

internal/collect/collector.go

@@ -68,10 +68,35 @@ type sampled struct {
 	A   any
 	B   any
 	Err error
-	// OwnTxns is how many transactions pgbot itself committed inside the sample
-	// window [A, B] — the wait sampler's successful polls. Only the health
-	// collector receives it, and subtracts it from the commit delta (PR#1).
-	OwnTxns int64
+	// Span is the MEASURED wall-clock time between this collector's own A and B
+	// samples — the divisor its rates deserve. Only health's samples bracket the
+	// runner window exactly; the other counters are sampled in phase 1 (before
+	// the window opens) and phase 2 (after it closes), so their true span is
+	// longer than the window, and dividing by the window would inflate every
+	// rate by that lead+lag — worst on short intervals and remote databases
+	// (bug_report.md N4). AtA/AtB are the raw stamps the runner fills; Span is
+	// their difference (health: exactly the window). Zero Span means unstamped
+	// (e.g. assembled without the runner); rateWindow falls back to the window.
+	AtA, AtB time.Time
+	Span     time.Duration
+	// OwnTxns / OwnTxnFails are how many transactions pgbot itself committed /
+	// aborted inside the sample window [A, B] — the wait sampler's successful
+	// and failed polls. Only the health collector receives them, and subtracts
+	// them from the commit/rollback deltas so pgbot never reports its own
+	// footprint as the database's workload (PR#1).
+	OwnTxns     int64
+	OwnTxnFails int64
+}
+
+// rateWindow is the divisor for this collector's rates: its own measured span
+// when the runner stamped one, else the runner window — and never a
+// non-positive interval (rate.PerSecond already refuses those, but callers
+// computing their own must not divide by zero).
+func (s sampled) rateWindow(fallback time.Duration) time.Duration {
+	if s.Span > 0 {
+		return s.Span
+	}
+	return fallback
 }
 
 // Collector reads one diagnostic domain and writes its section into the Context.

internal/collect/health.go

@@ -61,6 +61,7 @@ func (healthCollector) Assemble(c *model.Context, _ conn.Capabilities, s sampled
 		c.Health = &model.Health{Section: unavail(s.Err, "pg_stat_database unavailable")}
 		return
 	}
+	dt = s.rateWindow(dt) // health's own span — identical to the window
 	h := &model.Health{Connections: int(b.Numbackends)}
 	reset := false
 	mark := func(v *float64, ok bool) *float64 {
@@ -70,17 +71,33 @@ func (healthCollector) Assemble(c *model.Context, _ conn.Capabilities, s sampled
 		}
 		return v
 	}
-	// pgbot's own commits inside the window (the wait sampler's polls) are not the
-	// database's throughput: take them off sample B's commit counter before
-	// computing rates. Clamped so a reset (b < a) is still detected as such (PR#1).
+	// pgbot's own transactions inside the window are not the database's
+	// workload: take them off sample B's counters before computing rates.
+	// Every one of pgbot's reads books a server transaction (implicit or
+	// explicit): the wait sampler's successful polls commit (OwnTxns), its
+	// failed polls — a timeout/cancel mid-query — abort and book a ROLLBACK
+	// (OwnTxnFails), and health's own sample-A query commits inside the window
+	// (+1). The rollback subtraction is best-effort: a poll that fails before a
+	// backend is acquired books nothing, but under-counting pgbot's rollbacks
+	// is strictly safer than leaving them in — the leak fired false
+	// high-rollback-ratio findings during exactly the lock storms that stall
+	// polls. Clamped so a reset (b < a) is still detected as such (PR#1).
 	commitsB := b.XactCommit
-	if own := s.OwnTxns; own > 0 && commitsB-own >= a.XactCommit {
+	ownCommits := s.OwnTxns
+	if s.Err == nil {
+		ownCommits++ // health's sample-A transaction (its commit lands inside [A, B])
+	}
+	if own := ownCommits; own > 0 && commitsB-own >= a.XactCommit {
 		commitsB -= own
 	}
-	h.TPS = mark(rate.PerSecond(a.XactCommit+a.XactRollback, commitsB+b.XactRollback, dt))
+	rollbacksB := b.XactRollback
+	if own := s.OwnTxnFails; own > 0 && rollbacksB-own >= a.XactRollback {
+		rollbacksB -= own
+	}
+	h.TPS = mark(rate.PerSecond(a.XactCommit+a.XactRollback, commitsB+rollbacksB, dt))
 	h.CommitsPerSec = mark(rate.PerSecond(a.XactCommit, commitsB, dt))
-	h.RollbacksPerSec = mark(rate.PerSecond(a.XactRollback, b.XactRollback, dt))
-	if rr, ok := rate.Ratio(a.XactRollback, b.XactRollback, a.XactCommit, commitsB); ok {
+	h.RollbacksPerSec = mark(rate.PerSecond(a.XactRollback, rollbacksB, dt))
+	if rr, ok := rate.Ratio(a.XactRollback, rollbacksB, a.XactCommit, commitsB); ok {
 		h.RollbackRatio = round4p(rr)
 	}
 	if chr, ok := rate.Ratio(a.BlksHit, b.BlksHit, a.BlksRead, b.BlksRead); ok {