logging: fix db_query_time always reporting zero (#116824)

pkg/infra/log/databaseQueryTimer.go

@@ -18,7 +18,7 @@ func InitDBQueryTimer(ctx context.Context) context.Context {
 // IncDBQueryTimer increments the database query timer on the context.
 func IncDBQueryTimer(ctx context.Context, queryTimeInMs int64) context.Context {
 	if val := ctx.Value(dbCallQueryTimerKey); val == nil {
-		ctx = InitCounter(ctx)
+		ctx = InitDBQueryTimer(ctx)
 	}
 
 	if val := ctx.Value(dbCallQueryTimerKey); val != nil {

pkg/infra/log/databaseQueryTimer_test.go

@@ -0,0 +1,42 @@
+package log
+
+import (
+	"context"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestDatabaseQueryTimer(t *testing.T) {
+	testCases := []struct {
+		name       string
+		queryTimes []int64
+		expected   int64
+	}{
+		{
+			name:       "accumulates multiple query times",
+			queryTimes: []int64{100, 50, 25},
+			expected:   175,
+		},
+		{
+			name:       "single query time",
+			queryTimes: []int64{42},
+			expected:   42,
+		},
+		{
+			name:       "no queries returns zero",
+			queryTimes: []int64{},
+			expected:   0,
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			ctx := context.Background()
+			for _, queryTime := range tc.queryTimes {
+				ctx = IncDBQueryTimer(ctx, queryTime)
+			}
+			assert.Equal(t, tc.expected, TotalDBQueryTime(ctx))
+		})
+	}
+}

pkg/middleware/loggermw/logger.go

@@ -59,8 +59,9 @@ func (l *loggerImpl) Middleware() web.Middleware {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			start := time.Now()
 
-			// we have to init the context with the counter here to update the request
+			// we have to init the context with the counter and timer here to update the request
 			r = r.WithContext(log.InitCounter(r.Context()))
+			r = r.WithContext(log.InitDBQueryTimer(r.Context()))
 			// put the start time on context so we can measure it later.
 			r = r.WithContext(log.InitstartTime(r.Context(), time.Now()))
 

pkg/middleware/loggermw/logger_test.go

@@ -10,6 +10,7 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"github.com/grafana/grafana/pkg/apimachinery/errutil"
+	"github.com/grafana/grafana/pkg/infra/log"
 	contextmodel "github.com/grafana/grafana/pkg/services/contexthandler/model"
 	"github.com/grafana/grafana/pkg/services/featuremgmt"
 	"github.com/grafana/grafana/pkg/setting"
@@ -174,3 +175,39 @@ func (m mockResponseWriter) Status() int {
 func (m mockResponseWriter) Size() int {
 	return m.size
 }
+
+func TestMiddleware_InitializesDBQueryTimer(t *testing.T) {
+	cfg := setting.NewCfg()
+	l := Provide(cfg, featuremgmt.WithFeatures())
+
+	var capturedDBQueryTime int64
+	handler := l.Middleware()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		log.IncDBQueryTimer(r.Context(), 100)
+		log.IncDBQueryTimer(r.Context(), 50)
+		log.IncDBQueryTimer(r.Context(), 25)
+		capturedDBQueryTime = log.TotalDBQueryTime(r.Context())
+	}))
+
+	req := mustRequest(http.NewRequest(http.MethodGet, "/", nil))
+	handler.ServeHTTP(nil, req)
+
+	assert.Equal(t, int64(175), capturedDBQueryTime)
+}
+
+func TestMiddleware_InitializesDBCallCounter(t *testing.T) {
+	cfg := setting.NewCfg()
+	l := Provide(cfg, featuremgmt.WithFeatures())
+
+	var capturedDBCallCount int64
+	handler := l.Middleware()(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		log.IncDBCallCounter(r.Context())
+		log.IncDBCallCounter(r.Context())
+		log.IncDBCallCounter(r.Context())
+		capturedDBCallCount = log.TotalDBCallCount(r.Context())
+	}))
+
+	req := mustRequest(http.NewRequest(http.MethodGet, "/", nil))
+	handler.ServeHTTP(nil, req)
+
+	assert.Equal(t, int64(3), capturedDBCallCount)
+}