user-system/internal/api/middleware/logger.go

package middleware

import (
	"fmt"
	"log"
	"net/url"
	"strings"
	"time"

	"github.com/gin-gonic/gin"
)

var sensitiveQueryKeys = map[string]struct{}{
	"token":         {},
	"access_token":  {},
	"refresh_token": {},
	"code":          {},
	"secret":        {},
}

// logEntry is a single access-log line sent to the async writer.
type logEntry struct {
	ts        time.Time
	method    string
	path      string
	rawQuery  string
	status    int
	latency   time.Duration
	ip        string
	userAgent string
	userID    interface{}
	traceID   string
	errors    []string
}

// asyncLogger holds a channel-based write queue so that access log I/O is
// decoupled from the HTTP request handling goroutine.
//
// Buffer depth of 4096 means we can absorb ~4 k outstanding log lines before
// back-pressure is applied.  Under normal load (< 500 req/s) this buffer never
// fills; under load-test peaks it prevents log writes from inflating p99.
var asyncLogCh = func() chan logEntry {
	ch := make(chan logEntry, 4096)
	go func() {
		for e := range ch {
			writeLogEntry(e)
		}
	}()
	return ch
}()

func writeLogEntry(e logEntry) {
	log.Printf("[API] %s %s %s | status: %d | latency: %v | ip: %s | user_id: %v | trace_id: %s | ua: %s",
		e.ts.Format("2006-01-02 15:04:05"),
		e.method,
		e.path,
		e.status,
		e.latency,
		e.ip,
		e.userID,
		e.traceID,
		e.userAgent,
	)
	for _, errMsg := range e.errors {
		log.Printf("[Error] trace_id: %s | %s", e.traceID, errMsg)
	}
	if e.rawQuery != "" {
		log.Printf("[Query] %s?%s", e.path, e.rawQuery)
	}
}

// Logger returns a gin middleware that records each HTTP request.
// Log writes are offloaded to a background goroutine via a buffered channel,
// so they never block the handler goroutine or inflate response latency.
func Logger() gin.HandlerFunc {
	return func(c *gin.Context) {
		start := time.Now()
		path := c.Request.URL.Path
		raw := sanitizeQuery(c.Request.URL.RawQuery)

		c.Next()

		latency := time.Since(start)
		userID, _ := c.Get("user_id")
		traceID := GetTraceID(c)

		var errStrings []string
		for _, err := range c.Errors {
			errStrings = append(errStrings, fmt.Sprintf("%v", err))
		}

		entry := logEntry{
			ts:        time.Now(),
			method:    c.Request.Method,
			path:      path,
			rawQuery:  raw,
			status:    c.Writer.Status(),
			latency:   latency,
			ip:        c.ClientIP(),
			userAgent: c.Request.UserAgent(),
			userID:    userID,
			traceID:   traceID,
			errors:    errStrings,
		}

		// Non-blocking send: if the channel is full (extreme overload), drop the log
		// line rather than stall the HTTP response.
		select {
		case asyncLogCh <- entry:
		default:
			// Channel full — log drop is preferable to adding latency.
		}
	}
}

func sanitizeQuery(raw string) string {
	if raw == "" {
		return ""
	}

	values, err := url.ParseQuery(raw)
	if err != nil {
		return ""
	}

	for key := range values {
		if isSensitiveQueryKey(key) {
			values.Set(key, "***")
		}
	}

	return values.Encode()
}

func isSensitiveQueryKey(key string) bool {
	normalized := strings.ToLower(strings.TrimSpace(key))
	if _, ok := sensitiveQueryKeys[normalized]; ok {
		return true
	}
	return strings.Contains(normalized, "token") || strings.Contains(normalized, "secret")
}