feat(api): add request logging and slow query detector. Make total counts optional by default on query APIs (#143)

Author: skylenet

docs/api.md

@@ -353,6 +353,17 @@ Available only when [indexing](#indexing) is enabled.
 | `GET` | `/index/query/runs` | Query indexed runs with PostgREST-style filtering, sorting, and pagination |
 | `GET` | `/index/query/test_stats` | Query test stat data with PostgREST-style filtering, sorting, and pagination |
 | `GET` | `/index/query/test_stats_block_logs` | Query per-block log data with PostgREST-style filtering, sorting, and pagination |
+| `GET` | `/index/query/suites` | Query suite data with PostgREST-style filtering, sorting, and pagination |
+
+#### Row count
+
+By default, query endpoints skip the `SELECT count(*)` for performance — the `total` field is omitted from the response. To request an exact row count, send the `Prefer: count=exact` header:
+
+```
+Prefer: count=exact
+```
+
+When present, the response includes `"total": <n>`. This follows the [PostgREST](https://docs.postgrest.org/en/stable/references/api/preferences.html#exact-count) convention. On large tables (e.g. `test_stats`) the count query can take several seconds, so only request it when needed (e.g. for pagination totals).
 
 ### Files (requires authentication unless `anonymous_read` is enabled)
 

pkg/api/gormlogger/gormlogger.go

@@ -0,0 +1,118 @@
+package gormlogger
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+)
+
+const maxSQLLength = 500
+
+// Logger adapts logrus to GORM's logger.Interface, surfacing slow queries
+// and errors while keeping normal queries silent.
+type Logger struct {
+	log           logrus.FieldLogger
+	slowThreshold time.Duration
+}
+
+// Compile-time interface check.
+var _ gormlogger.Interface = (*Logger)(nil)
+
+// New creates a Logger that warns on queries slower than slowThreshold.
+func New(log logrus.FieldLogger, slowThreshold time.Duration) *Logger {
+	return &Logger{
+		log:           log,
+		slowThreshold: slowThreshold,
+	}
+}
+
+// LogMode is a no-op; log level is controlled by logrus configuration.
+func (l *Logger) LogMode(_ gormlogger.LogLevel) gormlogger.Interface {
+	return l
+}
+
+// Info is a no-op; informational GORM messages are not surfaced.
+func (l *Logger) Info(_ context.Context, _ string, _ ...any) {}
+
+// Warn forwards GORM warnings to logrus.
+func (l *Logger) Warn(_ context.Context, msg string, args ...any) {
+	l.log.Warnf(msg, args...)
+}
+
+// Error forwards GORM errors to logrus.
+func (l *Logger) Error(_ context.Context, msg string, args ...any) {
+	l.log.Errorf(msg, args...)
+}
+
+// Trace is called by GORM after every query. It logs errors and slow
+// queries while keeping normal operations silent.
+func (l *Logger) Trace(
+	_ context.Context,
+	begin time.Time,
+	fc func() (sql string, rows int64),
+	err error,
+) {
+	duration := time.Since(begin)
+	sql, rows := fc()
+	sql = truncateSQL(sql)
+
+	if err != nil {
+		if errors.Is(err, gorm.ErrRecordNotFound) {
+			return
+		}
+
+		if isContextCanceled(err) {
+			l.log.WithField("duration", duration).
+				WithField("canceled", true).
+				WithField("sql", sql).
+				Warn("Query canceled")
+
+			return
+		}
+
+		l.log.WithError(err).
+			WithField("duration", duration).
+			WithField("rows", rows).
+			WithField("sql", sql).
+			Error("Query error")
+
+		return
+	}
+
+	if l.slowThreshold > 0 && duration >= l.slowThreshold {
+		l.log.WithField("duration", duration).
+			WithField("rows", rows).
+			WithField("sql", sql).
+			Warn(fmt.Sprintf("Slow query (>= %s)", l.slowThreshold))
+	}
+}
+
+// isContextCanceled checks whether err is caused by context cancellation
+// or deadline exceeded. It uses errors.Is first, then falls back to
+// string matching for SQLite driver compatibility.
+func isContextCanceled(err error) bool {
+	if errors.Is(err, context.Canceled) ||
+		errors.Is(err, context.DeadlineExceeded) {
+		return true
+	}
+
+	msg := err.Error()
+
+	return strings.Contains(msg, "context canceled") ||
+		strings.Contains(msg, "context deadline exceeded")
+}
+
+// truncateSQL shortens a SQL string to maxSQLLength to prevent log bloat.
+func truncateSQL(sql string) string {
+	if len(sql) > maxSQLLength {
+		return sql[:maxSQLLength] + "..."
+	}
+
+	return sql
+}

pkg/api/handlers_index.go

@@ -4,6 +4,7 @@ import (
 	"encoding/json"
 	"net/http"
 	"sort"
+	"strings"
 	"time"
 
 	"github.com/ethpandaops/benchmarkoor/pkg/api/indexstore"
@@ -185,6 +186,10 @@ func (s *server) handleQueryRuns(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	params.CountExact = strings.Contains(
+		r.Header.Get("Prefer"), "count=exact",
+	)
+
 	result, err := s.indexStore.QueryRuns(r.Context(), params)
 	if err != nil {
 		writeJSON(w, http.StatusInternalServerError,
@@ -211,6 +216,10 @@ func (s *server) handleQueryTestStats(
 		return
 	}
 
+	params.CountExact = strings.Contains(
+		r.Header.Get("Prefer"), "count=exact",
+	)
+
 	result, err := s.indexStore.QueryTestStats(r.Context(), params)
 	if err != nil {
 		writeJSON(w, http.StatusInternalServerError,
@@ -237,6 +246,10 @@ func (s *server) handleQuerySuites(
 		return
 	}
 
+	params.CountExact = strings.Contains(
+		r.Header.Get("Prefer"), "count=exact",
+	)
+
 	result, err := s.indexStore.QuerySuites(r.Context(), params)
 	if err != nil {
 		writeJSON(w, http.StatusInternalServerError,
@@ -263,6 +276,10 @@ func (s *server) handleQueryTestStatsBlockLogs(
 		return
 	}
 
+	params.CountExact = strings.Contains(
+		r.Header.Get("Prefer"), "count=exact",
+	)
+
 	result, err := s.indexStore.QueryTestStatsBlockLogs(
 		r.Context(), params,
 	)

pkg/api/indexstore/indexstore.go

@@ -6,12 +6,12 @@ import (
 	"strings"
 	"time"
 
+	"github.com/ethpandaops/benchmarkoor/pkg/api/gormlogger"
 	"github.com/ethpandaops/benchmarkoor/pkg/config"
 	"github.com/glebarez/sqlite"
 	"github.com/sirupsen/logrus"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
-	"gorm.io/gorm/logger"
 )
 
 // Store provides persistence for the indexed benchmark data.
@@ -91,7 +91,7 @@ func NewStore(
 // Start opens the database connection and runs migrations.
 func (s *store) Start(ctx context.Context) error {
 	gormCfg := &gorm.Config{
-		Logger: logger.Discard,
+		Logger: gormlogger.New(s.log, 500*time.Millisecond),
 	}
 
 	switch s.cfg.Driver {
@@ -628,9 +628,15 @@ func (s *store) QueryRuns(
 		return scanMaps(q, params)
 	}
 
-	var total int64
-	if err := q.Count(&total).Error; err != nil {
-		return nil, fmt.Errorf("counting runs: %w", err)
+	var totalPtr *int64
+
+	if params.CountExact {
+		var total int64
+		if err := q.Count(&total).Error; err != nil {
+			return nil, fmt.Errorf("counting runs: %w", err)
+		}
+
+		totalPtr = &total
 	}
 
 	var runs []Run
@@ -647,7 +653,7 @@ func (s *store) QueryRuns(
 
 	return &QueryResult{
 		Data:   data,
-		Total:  total,
+		Total:  totalPtr,
 		Limit:  params.Limit,
 		Offset: params.Offset,
 	}, nil
@@ -669,9 +675,15 @@ func (s *store) QueryTestStats(
 		return scanMaps(q, params)
 	}
 
-	var total int64
-	if err := q.Count(&total).Error; err != nil {
-		return nil, fmt.Errorf("counting test stats: %w", err)
+	var totalPtr *int64
+
+	if params.CountExact {
+		var total int64
+		if err := q.Count(&total).Error; err != nil {
+			return nil, fmt.Errorf("counting test stats: %w", err)
+		}
+
+		totalPtr = &total
 	}
 
 	var stats []TestStat
@@ -688,7 +700,7 @@ func (s *store) QueryTestStats(
 
 	return &QueryResult{
 		Data:   data,
-		Total:  total,
+		Total:  totalPtr,
 		Limit:  params.Limit,
 		Offset: params.Offset,
 	}, nil
@@ -710,11 +722,17 @@ func (s *store) QueryTestStatsBlockLogs(
 		return scanMaps(q, params)
 	}
 
-	var total int64
-	if err := q.Count(&total).Error; err != nil {
-		return nil, fmt.Errorf(
-			"counting test stats block logs: %w", err,
-		)
+	var totalPtr *int64
+
+	if params.CountExact {
+		var total int64
+		if err := q.Count(&total).Error; err != nil {
+			return nil, fmt.Errorf(
+				"counting test stats block logs: %w", err,
+			)
+		}
+
+		totalPtr = &total
 	}
 
 	var logs []TestStatsBlockLog
@@ -733,7 +751,7 @@ func (s *store) QueryTestStatsBlockLogs(
 
 	return &QueryResult{
 		Data:   data,
-		Total:  total,
+		Total:  totalPtr,
 		Limit:  params.Limit,
 		Offset: params.Offset,
 	}, nil
@@ -753,9 +771,15 @@ func (s *store) QuerySuites(
 		return scanMaps(q, params)
 	}
 
-	var total int64
-	if err := q.Count(&total).Error; err != nil {
-		return nil, fmt.Errorf("counting suites: %w", err)
+	var totalPtr *int64
+
+	if params.CountExact {
+		var total int64
+		if err := q.Count(&total).Error; err != nil {
+			return nil, fmt.Errorf("counting suites: %w", err)
+		}
+
+		totalPtr = &total
 	}
 
 	var suites []Suite
@@ -772,7 +796,7 @@ func (s *store) QuerySuites(
 
 	return &QueryResult{
 		Data:   data,
-		Total:  total,
+		Total:  totalPtr,
 		Limit:  params.Limit,
 		Offset: params.Offset,
 	}, nil
@@ -845,9 +869,15 @@ func isSQLiteTransient(err error) bool {
 func scanMaps(
 	q *gorm.DB, params *QueryParams,
 ) (*QueryResult, error) {
-	var total int64
-	if err := q.Count(&total).Error; err != nil {
-		return nil, fmt.Errorf("counting rows: %w", err)
+	var totalPtr *int64
+
+	if params.CountExact {
+		var total int64
+		if err := q.Count(&total).Error; err != nil {
+			return nil, fmt.Errorf("counting rows: %w", err)
+		}
+
+		totalPtr = &total
 	}
 
 	var rows []map[string]any
@@ -859,7 +889,7 @@ func scanMaps(
 
 	return &QueryResult{
 		Data:   rows,
-		Total:  total,
+		Total:  totalPtr,
 		Limit:  params.Limit,
 		Offset: params.Offset,
 	}, nil

pkg/api/indexstore/query.go

@@ -160,19 +160,20 @@ type Order struct {
 
 // QueryParams holds the validated, parsed query parameters.
 type QueryParams struct {
-	Filters []Filter
-	Orders  []Order
-	Limit   int
-	Offset  int
-	Select  []string
+	Filters    []Filter
+	Orders     []Order
+	Limit      int
+	Offset     int
+	Select     []string
+	CountExact bool
 }
 
 // QueryResult wraps the paginated response.
 type QueryResult struct {
-	Data   any   `json:"data"`
-	Total  int64 `json:"total"`
-	Limit  int   `json:"limit"`
-	Offset int   `json:"offset"`
+	Data   any    `json:"data"`
+	Total  *int64 `json:"total,omitempty"`
+	Limit  int    `json:"limit"`
+	Offset int    `json:"offset"`
 }
 
 // RunResponse is the JSON DTO for a runs row.