diff --git a/internal/core/logging.go b/internal/core/logging.go new file mode 100644 index 0000000..8509f6a --- /dev/null +++ b/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() +} diff --git a/internal/core/logging_test.go b/internal/core/logging_test.go new file mode 100644 index 0000000..600bef0 --- /dev/null +++ b/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) + } + } +} diff --git a/internal/core/module.go b/internal/core/module.go index eb3dcd3..4afdb6f 100644 --- a/internal/core/module.go +++ b/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. diff --git a/mirrorstack.go b/mirrorstack.go index da67b7f..2c3cb9d 100644 --- a/mirrorstack.go +++ b/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,