fix: uniform gin context errors, fire-and-forget context safety, zerolog GORM adapter (#639)

lakhansamani · web-flow · commit 9a43e9837abc · 2026-06-17T13:29:37.000+05:30
* refactor(storage): replace stdlib GORM logger with zerolog adapter

The stdlib stderr logger introduced in the previous commit emitted
unstructured plain-text lines on stderr, inconsistent with the rest
of the app. The zerolog adapter implements logger.Interface directly,
routing all GORM diagnostics (errors, slow queries, SQL traces) as
structured JSON through the app's own zerolog instance.

Stdout safety is preserved — and now explicitly regression-anchored
by a unit test that pipes os.Stdout and asserts nothing is written,
directly encoding the invariant that protects the MCP stdio stream.

* fix: apply context.WithoutCancel to HTTP handler goroutines and fix errcheck lint

- oauth_callback.go and verify_email.go fire-and-forget goroutines now
  use context.WithoutCancel so session writes and webhook events survive
  after the request handler returns and Gin cancels the request context
- Capture UserAgent/IP before goroutine launch to avoid referencing the
  gin.Context after it may be recycled
- Fix errcheck lint: check errors from os.Pipe w.Close() and
  bytes.Buffer.ReadFrom() in gorm_logger_test.go
diff --git a/internal/http_handlers/oauth_callback.go b/internal/http_handlers/oauth_callback.go
@@ -1,6 +1,7 @@
 package http_handlers
 
 import (
+	"context"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -352,18 +353,21 @@ func (h *httpProvider) OAuthCallbackHandler() gin.HandlerFunc {
 			_ = h.MemoryStoreProvider.SetUserSession(sessionKey, constants.TokenTypeRefreshToken+"_"+authToken.FingerPrint, authToken.RefreshToken.Token, authToken.RefreshToken.ExpiresAt)
 		}
 
+		bgCtx := context.WithoutCancel(ctx)
+		userAgent := utils.GetUserAgent(ctx.Request)
+		ip := utils.GetIP(ctx.Request)
 		go func() {
 			if isSignUp {
-				_ = h.EventsProvider.RegisterEvent(ctx, constants.UserSignUpWebhookEvent, provider, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserSignUpWebhookEvent, provider, user)
 				// User is also logged in with signup
-				_ = h.EventsProvider.RegisterEvent(ctx, constants.UserLoginWebhookEvent, provider, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserLoginWebhookEvent, provider, user)
 			} else {
-				_ = h.EventsProvider.RegisterEvent(ctx, constants.UserLoginWebhookEvent, provider, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserLoginWebhookEvent, provider, user)
 			}
-			if err := h.StorageProvider.AddSession(ctx, &schemas.Session{
+			if err := h.StorageProvider.AddSession(bgCtx, &schemas.Session{
 				UserID:    user.ID,
-				UserAgent: utils.GetUserAgent(ctx.Request),
-				IP:        utils.GetIP(ctx.Request),
+				UserAgent: userAgent,
+				IP:        ip,
 			}); err != nil {
 				log.Debug().Err(err).Msg("Failed to add session")
 			}
diff --git a/internal/http_handlers/verify_email.go b/internal/http_handlers/verify_email.go
@@ -1,6 +1,7 @@
 package http_handlers
 
 import (
+	"context"
 	"net/http"
 	"strconv"
 	"strings"
@@ -225,18 +226,21 @@ func (h *httpProvider) VerifyEmailHandler() gin.HandlerFunc {
 			IPAddress:    utils.GetIP(c.Request),
 			UserAgent:    utils.GetUserAgent(c.Request),
 		})
+		bgCtx := context.WithoutCancel(c)
+		userAgent := utils.GetUserAgent(c.Request)
+		ip := utils.GetIP(c.Request)
 		go func() {
 			if isSignUp {
-				_ = h.EventsProvider.RegisterEvent(c, constants.UserSignUpWebhookEvent, loginMethod, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserSignUpWebhookEvent, loginMethod, user)
 				// User is also logged in with signup
-				_ = h.EventsProvider.RegisterEvent(c, constants.UserLoginWebhookEvent, loginMethod, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserLoginWebhookEvent, loginMethod, user)
 			} else {
-				_ = h.EventsProvider.RegisterEvent(c, constants.UserLoginWebhookEvent, loginMethod, user)
+				_ = h.EventsProvider.RegisterEvent(bgCtx, constants.UserLoginWebhookEvent, loginMethod, user)
 			}
-			if err := h.StorageProvider.AddSession(c, &schemas.Session{
+			if err := h.StorageProvider.AddSession(bgCtx, &schemas.Session{
 				UserID:    user.ID,
-				UserAgent: utils.GetUserAgent(c.Request),
-				IP:        utils.GetIP(c.Request),
+				UserAgent: userAgent,
+				IP:        ip,
 			}); err != nil {
 				log.Debug().Err(err).Msg("Error adding session")
 			}
diff --git a/internal/storage/db/sql/gorm_logger.go b/internal/storage/db/sql/gorm_logger.go
@@ -0,0 +1,96 @@
+package sql
+
+import (
+	"context"
+	"errors"
+	"time"
+
+	"github.com/rs/zerolog"
+	"gorm.io/gorm/logger"
+)
+
+// zerologGORMLogger adapts zerolog to GORM's logger.Interface so that all GORM
+// diagnostics (errors, slow queries, statement traces) are emitted as structured
+// JSON on the same logger as the rest of the application — never on os.Stdout.
+//
+// This is critical for the MCP stdio server, which uses stdout as its JSON-RPC
+// transport: any stray plain-text line from GORM's default os.Stdout logger
+// would corrupt the stream.
+type zerologGORMLogger struct {
+	log                  zerolog.Logger
+	level                logger.LogLevel
+	slowThreshold        time.Duration
+	ignoreRecordNotFound bool
+}
+
+func newZerologGORMLogger(log *zerolog.Logger) logger.Interface {
+	return &zerologGORMLogger{
+		log:                  log.With().Str("component", "gorm").Logger(),
+		level:                logger.Warn,
+		slowThreshold:        200 * time.Millisecond,
+		ignoreRecordNotFound: true,
+	}
+}
+
+func (l *zerologGORMLogger) LogMode(level logger.LogLevel) logger.Interface {
+	clone := *l
+	clone.level = level
+	return &clone
+}
+
+func (l *zerologGORMLogger) Info(_ context.Context, msg string, args ...interface{}) {
+	if l.level >= logger.Info {
+		l.log.Info().Msgf(msg, args...)
+	}
+}
+
+func (l *zerologGORMLogger) Warn(_ context.Context, msg string, args ...interface{}) {
+	if l.level >= logger.Warn {
+		l.log.Warn().Msgf(msg, args...)
+	}
+}
+
+func (l *zerologGORMLogger) Error(_ context.Context, msg string, args ...interface{}) {
+	if l.level >= logger.Error {
+		l.log.Error().Msgf(msg, args...)
+	}
+}
+
+// Trace logs SQL statements. Errors surface at error level, slow queries at
+// warn level, and everything else at debug level (only when LogLevel >= Info).
+func (l *zerologGORMLogger) Trace(_ context.Context, begin time.Time, fc func() (string, int64), err error) {
+	if l.level <= logger.Silent {
+		return
+	}
+	elapsed := time.Since(begin)
+	sql, rows := fc()
+
+	switch {
+	case err != nil && l.level >= logger.Error &&
+		(!errors.Is(err, logger.ErrRecordNotFound) || !l.ignoreRecordNotFound):
+		l.log.Error().
+			Err(err).
+			Str("sql", sql).
+			Int64("rows", rows).
+			Dur("duration", elapsed).
+			Msg("gorm error")
+
+	case elapsed > l.slowThreshold && l.slowThreshold != 0 && l.level >= logger.Warn:
+		l.log.Warn().
+			Str("sql", sql).
+			Int64("rows", rows).
+			Dur("duration", elapsed).
+			Str("slow_threshold", l.slowThreshold.String()).
+			Msg("slow sql")
+
+	case l.level >= logger.Info:
+		l.log.Debug().
+			Str("sql", sql).
+			Int64("rows", rows).
+			Dur("duration", elapsed).
+			Msg("sql")
+	}
+}
+
+// compile-time assertion that zerologGORMLogger satisfies the interface.
+var _ logger.Interface = (*zerologGORMLogger)(nil)
diff --git a/internal/storage/db/sql/gorm_logger_test.go b/internal/storage/db/sql/gorm_logger_test.go
@@ -0,0 +1,191 @@
+package sql
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"errors"
+	"os"
+	"testing"
+	"time"
+
+	"github.com/rs/zerolog"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm/logger"
+)
+
+// newTestLogger returns a zerologGORMLogger that writes to buf and the
+// underlying zerolog.Logger so callers can inspect emitted JSON.
+func newTestLogger(buf *bytes.Buffer) logger.Interface {
+	zl := zerolog.New(buf).With().Timestamp().Logger()
+	return newZerologGORMLogger(&zl)
+}
+
+func loggedFields(t *testing.T, buf *bytes.Buffer) map[string]interface{} {
+	t.Helper()
+	var m map[string]interface{}
+	require.NoError(t, json.Unmarshal(buf.Bytes(), &m), "invalid JSON from logger: %s", buf.String())
+	return m
+}
+
+func TestZerologGORMLogger_Trace(t *testing.T) {
+	ctx := context.Background()
+
+	t.Run("normal query at Info level emits debug message", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Info)
+
+		l.Trace(ctx, time.Now(), func() (string, int64) { return "SELECT 1", 1 }, nil)
+
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "debug", fields["level"])
+		assert.Equal(t, "sql", fields["message"])
+		assert.Equal(t, "SELECT 1", fields["sql"])
+	})
+
+	t.Run("normal query at Warn level emits nothing", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf) // default level = Warn
+
+		l.Trace(ctx, time.Now(), func() (string, int64) { return "SELECT 1", 1 }, nil)
+
+		assert.Empty(t, buf.Bytes(), "no output expected at Warn level for a fast non-error query")
+	})
+
+	t.Run("slow query emits warn message", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf) // default slowThreshold = 200ms
+
+		begin := time.Now().Add(-500 * time.Millisecond)
+		l.Trace(ctx, begin, func() (string, int64) { return "SELECT slow", 10 }, nil)
+
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "warn", fields["level"])
+		assert.Equal(t, "slow sql", fields["message"])
+		assert.Equal(t, "SELECT slow", fields["sql"])
+		assert.NotNil(t, fields["slow_threshold"])
+	})
+
+	t.Run("real error emits error message", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf)
+
+		l.Trace(ctx, time.Now(), func() (string, int64) { return "INSERT bad", 0 }, errors.New("constraint violation"))
+
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "error", fields["level"])
+		assert.Equal(t, "gorm error", fields["message"])
+		assert.Equal(t, "INSERT bad", fields["sql"])
+		assert.Contains(t, fields["error"], "constraint violation")
+	})
+
+	t.Run("ErrRecordNotFound is suppressed by default", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf)
+
+		l.Trace(ctx, time.Now(), func() (string, int64) { return "SELECT missing", 0 }, logger.ErrRecordNotFound)
+
+		assert.Empty(t, buf.Bytes(), "ErrRecordNotFound should be silenced when ignoreRecordNotFound=true")
+	})
+
+	t.Run("ErrRecordNotFound surfaces when ignoreRecordNotFound=false", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		zl := zerolog.New(buf)
+		l := &zerologGORMLogger{
+			log:                  zl.With().Str("component", "gorm").Logger(),
+			level:                logger.Error,
+			slowThreshold:        200 * time.Millisecond,
+			ignoreRecordNotFound: false,
+		}
+
+		l.Trace(ctx, time.Now(), func() (string, int64) { return "SELECT missing", 0 }, logger.ErrRecordNotFound)
+
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "error", fields["level"])
+		assert.Equal(t, "gorm error", fields["message"])
+	})
+
+	t.Run("Silent level suppresses all output", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Silent)
+
+		l.Trace(ctx, time.Now().Add(-time.Second), func() (string, int64) { return "SELECT 1", 1 }, errors.New("boom"))
+
+		assert.Empty(t, buf.Bytes())
+	})
+}
+
+func TestZerologGORMLogger_InfoWarnError(t *testing.T) {
+	ctx := context.Background()
+
+	t.Run("Info logs at info level when level>=Info", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Info)
+		l.Info(ctx, "test info %s", "msg")
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "info", fields["level"])
+	})
+
+	t.Run("Info suppressed when level<Info", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Warn)
+		l.Info(ctx, "should not appear")
+		assert.Empty(t, buf.Bytes())
+	})
+
+	t.Run("Warn logs at warn level", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Warn)
+		l.Warn(ctx, "slow thing %d", 42)
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "warn", fields["level"])
+	})
+
+	t.Run("Error logs at error level", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		l := newTestLogger(buf).LogMode(logger.Error)
+		l.Error(ctx, "something broke")
+		fields := loggedFields(t, buf)
+		assert.Equal(t, "error", fields["level"])
+	})
+}
+
+func TestZerologGORMLogger_LogMode(t *testing.T) {
+	buf := &bytes.Buffer{}
+	base := newTestLogger(buf)
+	clone := base.LogMode(logger.Info)
+
+	// clone must be independent of base
+	assert.NotSame(t, base, clone)
+}
+
+// TestZerologGORMLogger_StdoutSafety verifies that no bytes land on os.Stdout
+// when the logger emits errors or slow-query warnings — the invariant that
+// protects the MCP stdio JSON-RPC stream from corruption.
+func TestZerologGORMLogger_StdoutSafety(t *testing.T) {
+	ctx := context.Background()
+
+	origStdout := os.Stdout
+	r, w, err := os.Pipe()
+	require.NoError(t, err)
+	os.Stdout = w
+
+	buf := &bytes.Buffer{}
+	l := newTestLogger(buf).LogMode(logger.Info)
+
+	// error path
+	l.Trace(ctx, time.Now(), func() (string, int64) { return "SELECT 1", 0 }, errors.New("boom"))
+	// slow-query path
+	l.Trace(ctx, time.Now().Add(-time.Second), func() (string, int64) { return "SELECT slow", 1 }, nil)
+	// info path
+	l.Info(ctx, "hello")
+
+	require.NoError(t, w.Close())
+	os.Stdout = origStdout
+
+	captured := &bytes.Buffer{}
+	_, err = captured.ReadFrom(r)
+	require.NoError(t, err)
+	assert.Empty(t, captured.Bytes(), "zerologGORMLogger must never write to os.Stdout")
+}
diff --git a/internal/storage/db/sql/provider.go b/internal/storage/db/sql/provider.go
