From 6c130389fe99d597144c0ea05d5b748021791fbb Mon Sep 17 00:00:00 2001 From: Sheng Kun Chang Date: Tue, 30 Jun 2026 11:21:25 +0800 Subject: [PATCH] feat(sdk): emit one access line per request from requestLogMiddleware MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit requestLogMiddleware attached a per-request logger but never emitted, so a module's Logcat stayed empty unless the module called ms.Log itself. Emit one structured "request" line per request (method, path, status, duration_ms) from the already-tagged per-request logger, so the platform Logcat shows traffic out of the box for every module. Path only — a query string can carry OAuth state/tokens, which must never land in logs. statusRecorder captures the status (default 200) and forwards Flush so wrapping never silently disables an SSE handler. Co-Authored-By: Claude Opus 4.8 (1M context) --- internal/core/logging.go | 44 +++++++++++++++++++++++++++++++---- internal/core/logging_test.go | 35 ++++++++++++++++++++++++++++ 2 files changed, 74 insertions(+), 5 deletions(-) diff --git a/internal/core/logging.go b/internal/core/logging.go index 8509f6a..2c89793 100644 --- a/internal/core/logging.go +++ b/internal/core/logging.go @@ -6,6 +6,7 @@ import ( "net/http" "os" "strings" + "time" "github.com/aws/aws-lambda-go/lambdacontext" "github.com/mirrorstack-ai/app-module-sdk/auth" @@ -41,10 +42,12 @@ func parseLogLevel(s string) slog.Level { // requestLogMiddleware attaches a per-request *slog.Logger to the context, // pre-tagged with the trusted correlation fields so every ms.Log(ctx) line is -// attributable in the platform Logcat. It runs on BOTH serving paths (it only -// READS context): identity is already established upstream — the Lambda shim's -// InjectResources in prod, devAppSchemaMiddleware in dev — and app id is the -// trusted, unspoofable value (never a request field). +// attributable in the platform Logcat, and emits one access line per request so +// the Logcat shows traffic out of the box — even for modules that never call +// ms.Log themselves. It runs on BOTH serving paths (it only READS context): +// identity is already established upstream — the Lambda shim's InjectResources +// in prod, devAppSchemaMiddleware in dev — and app id is the trusted, +// unspoofable value (never a request field). func (m *Module) requestLogMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { ctx := r.Context() @@ -52,10 +55,41 @@ func (m *Module) requestLogMiddleware(next http.Handler) http.Handler { if id := auth.Get(ctx); id != nil { logger = logger.With("app_id", id.AppID, "user_id", id.UserID, "app_role", id.AppRole) } - next.ServeHTTP(w, r.WithContext(context.WithValue(ctx, logCtxKey{}, logger))) + rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + start := time.Now() + next.ServeHTTP(rec, r.WithContext(context.WithValue(ctx, logCtxKey{}, logger))) + // path only — a query string can carry OAuth state/tokens, which must + // never land in logs. status/duration give the Logcat a usable access + // trail without the module writing any log code of its own. + logger.LogAttrs(ctx, slog.LevelInfo, "request", + slog.String("method", r.Method), + slog.String("path", r.URL.Path), + slog.Int("status", rec.status), + slog.Int64("duration_ms", time.Since(start).Milliseconds()), + ) }) } +// statusRecorder captures the response status for the access line. It defaults +// to 200 — what net/http assumes when a handler writes a body without an +// explicit WriteHeader — and forwards Flush so wrapping never silently disables +// a streaming (SSE) handler. +type statusRecorder struct { + http.ResponseWriter + status int +} + +func (r *statusRecorder) WriteHeader(code int) { + r.status = code + r.ResponseWriter.WriteHeader(code) +} + +func (r *statusRecorder) Flush() { + if f, ok := r.ResponseWriter.(http.Flusher); ok { + f.Flush() + } +} + // requestID is the prod Lambda request id when present (so the module line shares // CloudWatch's own request grouping), else a fresh dev id. func requestID(ctx context.Context) string { diff --git a/internal/core/logging_test.go b/internal/core/logging_test.go index 600bef0..9261e01 100644 --- a/internal/core/logging_test.go +++ b/internal/core/logging_test.go @@ -80,3 +80,38 @@ func TestRequestLogMiddleware_TagsCorrelation(t *testing.T) { } } } + +func TestRequestLogMiddleware_EmitsAccessLine(t *testing.T) { + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, nil))) + t.Cleanup(func() { slog.SetDefault(prev) }) + + m := &Module{config: Config{ID: "oauthcore"}} + // A handler that sets a non-200 status and never calls ms.Log: the access + // line must still appear, with the status the handler wrote. + h := m.requestLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusForbidden) + })) + + req := httptest.NewRequest(http.MethodGet, "/public/start?state=secret", nil) + h.ServeHTTP(httptest.NewRecorder(), req) + + out := buf.String() + for _, want := range []string{ + `"msg":"request"`, + `"method":"GET"`, + `"path":"/public/start"`, + `"status":403`, + `"duration_ms":`, + `"module_id":"oauthcore"`, + } { + if !strings.Contains(out, want) { + t.Errorf("access line missing %s\ngot: %s", want, out) + } + } + // the query string (which can carry tokens) must never be logged + if strings.Contains(out, "state=secret") { + t.Errorf("access line leaked query string\ngot: %s", out) + } +}