feat(sdk): structured JSON logging + per-request ms.Log(ctx)

internal/core/logging.go

@@ -0,0 +1,75 @@
+package core
+
+import (
+	"context"
+	"log/slog"
+	"net/http"
+	"os"
+	"strings"
+
+	"github.com/aws/aws-lambda-go/lambdacontext"
+	"github.com/mirrorstack-ai/app-module-sdk/auth"
+	"github.com/mirrorstack-ai/app-module-sdk/internal/ids"
+)
+
+type logCtxKey struct{}
+
+// configureLogging installs a JSON slog handler on stdout as the process
+// default. Module logs (via ms.Log) and any slog call then emit one structured
+// JSON line per event, captured identically by CloudWatch (prod Lambda) and the
+// `mirrorstack dev` runner (dev) — so the platform Logcat reads one clean stream
+// with no transport code. Level is MS_LOG_LEVEL (debug|info|warn|error), default
+// info. The SDK's own stderr diagnostic logger (m.logger) is left as-is.
+func configureLogging() {
+	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
+		Level: parseLogLevel(os.Getenv("MS_LOG_LEVEL")),
+	})))
+}
+
+func parseLogLevel(s string) slog.Level {
+	switch strings.ToLower(strings.TrimSpace(s)) {
+	case "debug":
+		return slog.LevelDebug
+	case "warn", "warning":
+		return slog.LevelWarn
+	case "error":
+		return slog.LevelError
+	default:
+		return slog.LevelInfo
+	}
+}
+
+// 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).
+func (m *Module) requestLogMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
+		logger := slog.With("module_id", m.config.ID, "request_id", requestID(ctx))
+		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)))
+	})
+}
+
+// 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 {
+	if lc, ok := lambdacontext.FromContext(ctx); ok && lc.AwsRequestID != "" {
+		return lc.AwsRequestID
+	}
+	return ids.NewUUID()
+}
+
+// LoggerFrom returns the per-request logger attached by requestLogMiddleware, or
+// the process default if called outside a request. Exposed as ms.Log.
+func LoggerFrom(ctx context.Context) *slog.Logger {
+	if l, ok := ctx.Value(logCtxKey{}).(*slog.Logger); ok {
+		return l
+	}
+	return slog.Default()
+}

internal/core/logging_test.go

@@ -0,0 +1,82 @@
+package core
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/aws/aws-lambda-go/lambdacontext"
+	"github.com/mirrorstack-ai/app-module-sdk/auth"
+)
+
+func TestParseLogLevel(t *testing.T) {
+	cases := map[string]slog.Level{
+		"debug":    slog.LevelDebug,
+		"info":     slog.LevelInfo,
+		"":         slog.LevelInfo,
+		"nonsense": slog.LevelInfo,
+		"WARN":     slog.LevelWarn,
+		"warning":  slog.LevelWarn,
+		" error ":  slog.LevelError,
+	}
+	for in, want := range cases {
+		if got := parseLogLevel(in); got != want {
+			t.Errorf("parseLogLevel(%q) = %v, want %v", in, got, want)
+		}
+	}
+}
+
+func TestRequestID_PrefersAwsRequestID(t *testing.T) {
+	ctx := lambdacontext.NewContext(context.Background(), &lambdacontext.LambdaContext{AwsRequestID: "aws-req-1"})
+	if got := requestID(ctx); got != "aws-req-1" {
+		t.Errorf("requestID with lambda ctx = %q, want aws-req-1", got)
+	}
+	if got := requestID(context.Background()); got == "" {
+		t.Error("requestID without lambda ctx should mint a non-empty id")
+	}
+}
+
+func TestLoggerFrom_DefaultOutsideRequest(t *testing.T) {
+	if LoggerFrom(context.Background()) == nil {
+		t.Error("LoggerFrom must never return nil")
+	}
+}
+
+func TestRequestLogMiddleware_TagsCorrelation(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"}}
+	ran := false
+	h := m.requestLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		LoggerFrom(r.Context()).Info("hello")
+		ran = true
+	}))
+
+	req := httptest.NewRequest(http.MethodGet, "/", nil)
+	req = req.WithContext(auth.Set(req.Context(), auth.Identity{AppID: "app-1", UserID: "user-1", AppRole: "admin"}))
+	h.ServeHTTP(httptest.NewRecorder(), req)
+
+	if !ran {
+		t.Fatal("handler did not run")
+	}
+	out := buf.String()
+	for _, want := range []string{
+		`"module_id":"oauthcore"`,
+		`"app_id":"app-1"`,
+		`"user_id":"user-1"`,
+		`"app_role":"admin"`,
+		`"request_id":`,
+		`"msg":"hello"`,
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("log line missing %s\ngot: %s", want, out)
+		}
+	}
+}

internal/core/module.go

@@ -255,6 +255,14 @@ func New(cfg Config) (*Module, error) {
 		m.router.Use(m.devAppSchemaMiddleware)
 	}
 
+	// Structured logging: JSON to stdout (captured by CloudWatch in prod and the
+	// `mirrorstack dev` runner in dev) + a per-request correlated logger (ms.Log)
+	// carrying the trusted app_id/request_id/module_id. Mounted after the dev
+	// schema middleware so the request's identity is already in context; runs on
+	// every request, both serving paths.
+	configureLogging()
+	m.router.Use(m.requestLogMiddleware)
+
 	// Eagerly initialize SQS client when queue URL is configured.
 	// LoadDefaultConfig may hit IMDS on first cold start in Lambda; acceptable
 	// since this runs once at process init, not per request.

mirrorstack.go

@@ -10,6 +10,7 @@ import (
 	"context"
 	"encoding/json"
 	"io/fs"
+	"log/slog"
 	"net/http"
 
 	"github.com/go-chi/chi/v5"
@@ -267,6 +268,17 @@ func AppID(ctx context.Context) string {
 	return core.AppID(ctx)
 }
 
+// Log returns the request's structured logger, pre-tagged with the trusted
+// app_id / request_id / module_id correlation fields so every line is
+// attributable in the platform Logcat. Prefer it over the standard library
+// `log` for all module logging. Outside a request it returns the process
+// default logger.
+//
+//	ms.Log(r.Context()).Info("user signed in", "provider", "google")
+func Log(ctx context.Context) *slog.Logger {
+	return core.LoggerFrom(ctx)
+}
+
 // WithAppID returns a context whose inter-module Call scope is the given app,
 // overriding the ambient identity's app. ms.Call reads the app id from the
 // context (auth.Get) — for a handler that is the request's authenticated app,