feat: complete API-driven projects with infrastructure and business acceptance

middleware/middleware.go

@@ -2,6 +2,7 @@ package middleware
 
 import (
 	"fmt"
+	"runtime/debug"
 	"time"
 
 	apierrors "git.yuntuo.hk/k2safe/go-omni/errors"
@@ -37,6 +38,7 @@ func Recovery() httpx.Middleware {
 		return func(ctx *httpx.Context) (err error) {
 			defer func() {
 				if recovered := recover(); recovered != nil {
+					logx.ErrorContext(ctx.Context(), "http.panic", "panic", recovered, "stack", string(debug.Stack()), "method", ctx.Request().Method, "route", httpx.RoutePattern(ctx.Context()))
 					err = apierrors.Internal(fmt.Errorf("panic recovered: %v", recovered))
 				}
 			}()
@@ -48,7 +50,25 @@ func Recovery() httpx.Middleware {
 // AccessLog records one structured event after each request. It deliberately
 // lives in GoOmni instead of using a router-specific logger so business
 // applications get the same log format with every transport adapter.
-func AccessLog() httpx.Middleware {
+type AccessLogOption func(*accessLogConfig)
+type accessLogConfig struct{ slowThreshold time.Duration }
+
+// WithSlowRequestThreshold logs slow requests at WARN. Zero disables detection.
+func WithSlowRequestThreshold(threshold time.Duration) AccessLogOption {
+	return func(c *accessLogConfig) {
+		if threshold >= 0 {
+			c.slowThreshold = threshold
+		}
+	}
+}
+
+func AccessLog(options ...AccessLogOption) httpx.Middleware {
+	settings := accessLogConfig{}
+	for _, option := range options {
+		if option != nil {
+			option(&settings)
+		}
+	}
 	return func(next httpx.Handler) httpx.Handler {
 		return func(ctx *httpx.Context) error {
 			started := time.Now()
@@ -57,14 +77,30 @@ func AccessLog() httpx.Middleware {
 			if err != nil && !ctx.Responded() {
 				status = apierrors.From(err).Status
 			}
-			logx.InfoContext(ctx.Context(), "http.request",
+			duration := time.Since(started)
+			slow := settings.slowThreshold > 0 && duration >= settings.slowThreshold
+			attrs := []any{
 				"method", ctx.Request().Method,
 				"path", ctx.Request().URL.Path,
 				"route", httpx.RoutePattern(ctx.Context()),
 				"status", status,
-				"durationMs", time.Since(started).Seconds()*1000,
+				"durationMs", duration.Seconds() * 1000,
 				"clientIp", ctx.ClientIP(),
-			)
+			}
+			if slow {
+				attrs = append(attrs, "slow", true)
+			}
+			if err != nil {
+				attrs = append(attrs, "error", err)
+			}
+			switch {
+			case status >= 500:
+				logx.ErrorContext(ctx.Context(), "http.request", attrs...)
+			case slow:
+				logx.WarnContext(ctx.Context(), "http.request", attrs...)
+			default:
+				logx.InfoContext(ctx.Context(), "http.request", attrs...)
+			}
 			return err
 		}
 	}

middleware/middleware_test.go

@@ -4,8 +4,11 @@ import (
 	"bytes"
 	"encoding/json"
 	"errors"
+	"io"
 	"net/http/httptest"
+	"strings"
 	"testing"
+	"time"
 
 	apierrors "git.yuntuo.hk/k2safe/go-omni/errors"
 	"git.yuntuo.hk/k2safe/go-omni/httpx"
@@ -42,12 +45,19 @@ func TestAccessLogReportsCommittedStatus(t *testing.T) {
 				ctx.WriteError(err)
 			}
 			var entry struct {
+				Message   string `json:"msg"`
 				Status    int
 				Route     string
 				RequestID string `json:"requestId"`
 			}
-			if err := json.Unmarshal(output.Bytes(), &entry); err != nil {
-				t.Fatal(err)
+			decoder := json.NewDecoder(&output)
+			for {
+				if err := decoder.Decode(&entry); err != nil {
+					t.Fatal(err)
+				}
+				if entry.Message == "http.request" {
+					break
+				}
 			}
 			if entry.Status != tc.status || w.Code != tc.status || entry.Route != "/users/:id" || entry.RequestID != "logRequest" {
 				t.Fatalf("log=%s response=%d; expected status %d and request metadata", &output, w.Code, tc.status)
@@ -86,3 +96,48 @@ func TestAccessLogUsesVerifiedClientIP(t *testing.T) {
 		t.Fatalf("expected verified client IP, got %q", entry.ClientIP)
 	}
 }
+
+func TestSlowAndPanicLogs(t *testing.T) {
+	var out bytes.Buffer
+	logger, _ := logx.New(logx.Config{Writer: &out})
+	logx.SetDefault(logger)
+	defer logx.SetDefault(nil)
+	ctx := httpx.NewContext(httptest.NewRequest("GET", "/panic?secret=hidden", nil), httptest.NewRecorder(), nil)
+	chain := middleware.RequestID("X-Request-ID")(middleware.AccessLog(middleware.WithSlowRequestThreshold(time.Nanosecond))(middleware.Recovery()(func(c *httpx.Context) error { panic("boom") })))
+	err := chain(ctx)
+	if err == nil {
+		t.Fatal("panic not recovered")
+	}
+	decoder := json.NewDecoder(&out)
+	count := 0
+	for {
+		var entry map[string]any
+		err := decoder.Decode(&entry)
+		if err == io.EOF {
+			break
+		}
+		if err != nil {
+			t.Fatal(err)
+		}
+		count++
+		if entry["requestId"] == "" || entry["level"] != "ERROR" {
+			t.Fatal(entry)
+		}
+		if entry["msg"] == "http.panic" && !strings.Contains(entry["stack"].(string), "TestSlowAndPanicLogs") {
+			t.Fatal(entry)
+		}
+		if entry["msg"] == "http.request" && (entry["slow"] != true || entry["status"] != float64(500)) {
+			t.Fatal(entry)
+		}
+	}
+	if count != 2 {
+		t.Fatal(count)
+	}
+	out.Reset()
+	ctx = httpx.NewContext(httptest.NewRequest("GET", "/slow", nil), httptest.NewRecorder(), nil)
+	err = middleware.AccessLog(middleware.WithSlowRequestThreshold(time.Nanosecond))(func(c *httpx.Context) error { return c.OK("done") })(ctx)
+	var entry map[string]any
+	if err != nil || json.Unmarshal(out.Bytes(), &entry) != nil || entry["level"] != "WARN" || entry["slow"] != true {
+		t.Fatal(out.String(), err)
+	}
+}