From 56a8c10d155757c128efcc5a063104fe5770c8c0 Mon Sep 17 00:00:00 2001 From: Pramitha Jayasooriya Date: Wed, 15 Apr 2026 23:14:43 +0530 Subject: [PATCH] feat(go-common): add structured slog logger package MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Introduces packages/go-common/logger — a zero-dependency, context-aware structured logger built on the stdlib log/slog (Go 1.21+): - New / NewFromEnv: construct a JSON (prod) or text (dev) logger driven by LOG_LEVEL and LOG_FORMAT env vars; installs it as the process-wide default - WithContext / FromContext: store and retrieve a per-request logger; FromContext auto-enriches every record with tenant_id (from tenant.Middleware) and trace_id so handler code never has to thread these fields manually - WithTraceID / TraceIDFromContext: propagate trace IDs through context for distributed tracing support - HTTPMiddleware: request-logging middleware that captures method, path, status, latency, remote_addr, tenant_id and trace_id in one structured record; wraps ResponseWriter to record status without breaking http.Flusher / http.Hijacker via Unwrap() - 13 table-driven tests covering level filtering, context enrichment, tenant isolation, trace fallback (X-Request-ID), and non-2xx capture Co-Authored-By: Claude Sonnet 4.6 --- packages/go-common/logger/logger.go | 283 +++++++++++++++++++++++ packages/go-common/logger/logger_test.go | 273 ++++++++++++++++++++++ 2 files changed, 556 insertions(+) create mode 100644 packages/go-common/logger/logger.go create mode 100644 packages/go-common/logger/logger_test.go diff --git a/packages/go-common/logger/logger.go b/packages/go-common/logger/logger.go new file mode 100644 index 0000000..dcb9aa3 --- /dev/null +++ b/packages/go-common/logger/logger.go @@ -0,0 +1,283 @@ +/* + * Copyright (c) 2026, SoftlaneIT (https://softlaneit.com/) All Rights Reserved. + * + * SoftlaneIT licenses this file to you under the Apache License, + * Version 2.0 (the "LICENSE"); you may not use this file except + * in compliance with the LICENSE. + * You may obtain a copy of the LICENSE at + * + * https://softlaneit.com/LICENSE.txt + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the LICENSE is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the LICENSE for the + * specific language governing permissions and limitations + * under the LICENSE. + */ + +// Package logger provides a structured, context-aware logger for all ServiceForge +// services. It is built on top of the standard library's log/slog (Go 1.21+) +// and therefore carries zero third-party dependencies. +// +// # Typical service startup +// +// func main() { +// log := logger.NewFromEnv("booking-service") +// log.Info("service starting", slog.String("port", port)) +// ... +// handler := logger.HTTPMiddleware(log)(mux) +// } +// +// # Context propagation +// +// Every outgoing log record is enriched with the tenant_id and trace_id that +// are already stored in the request context. Use FromContext inside handlers: +// +// func (h *Handler) CreateBooking(w http.ResponseWriter, r *http.Request) { +// log := logger.FromContext(r.Context()) +// log.Info("creating booking", slog.String("customer", id)) +// } +// +// # Environment variables +// +// - LOG_LEVEL – debug | info | warn | error (default: info) +// - LOG_FORMAT – json | text (default: json) +package logger + +import ( + "context" + "log/slog" + "net/http" + "os" + "strings" + "time" + + "github.com/SoftLaneIT/serviceforge/packages/go-common/tenant" +) + +// ─── context keys ──────────────────────────────────────────────────────────── + +type ctxKey string + +const ( + loggerKey ctxKey = "sf_logger" + traceIDKey ctxKey = "sf_trace_id" +) + +// ─── Options ───────────────────────────────────────────────────────────────── + +// Options controls how a logger is constructed. +type Options struct { + // Level is the minimum log level that will be emitted. + // Accepted values (case-insensitive): "debug", "info", "warn", "error". + // Empty string defaults to "info". + Level string + + // Format selects the output encoding. + // "text" emits human-readable key=value lines; everything else emits JSON. + // JSON is the default because it is the format consumed by log aggregators + // (Loki, CloudWatch, ELK). + Format string + + // Service is emitted as a fixed "service" field on every log record so that + // log aggregation queries can filter by service name without parsing the + // message. + Service string +} + +// ─── Constructors ───────────────────────────────────────────────────────────── + +// New builds a *slog.Logger from opts, installs it as the process-wide default +// (slog.SetDefault), and returns it. Services that want an isolated logger +// without touching the default should use the returned value directly. +func New(opts Options) *slog.Logger { + handlerOpts := &slog.HandlerOptions{ + Level: parseLevel(opts.Level), + AddSource: parseLevel(opts.Level) == slog.LevelDebug, + } + + var handler slog.Handler + if strings.ToLower(opts.Format) == "text" { + handler = slog.NewTextHandler(os.Stdout, handlerOpts) + } else { + handler = slog.NewJSONHandler(os.Stdout, handlerOpts) + } + + l := slog.New(handler) + if opts.Service != "" { + l = l.With(slog.String("service", opts.Service)) + } + + slog.SetDefault(l) + return l +} + +// NewFromEnv is the standard entry-point for every ServiceForge binary. It +// reads LOG_LEVEL and LOG_FORMAT from the environment, sets the named service +// attribute, and registers the logger as the process-wide slog default. +// +// log := logger.NewFromEnv("tenant-service") +func NewFromEnv(service string) *slog.Logger { + return New(Options{ + Level: os.Getenv("LOG_LEVEL"), + Format: os.Getenv("LOG_FORMAT"), + Service: service, + }) +} + +// ─── Context helpers ────────────────────────────────────────────────────────── + +// WithContext stores l in ctx and returns the enriched context. Call this once +// per request (typically inside HTTPMiddleware) so that handler code can +// retrieve a pre-enriched logger via FromContext. +func WithContext(ctx context.Context, l *slog.Logger) context.Context { + return context.WithValue(ctx, loggerKey, l) +} + +// FromContext retrieves the logger stored by WithContext and returns a copy +// pre-enriched with any tenant_id and trace_id already present in ctx. +// If no logger was stored, the process-wide slog default is used as the base. +// +// This is the only logger retrieval function handler code should ever need. +func FromContext(ctx context.Context) *slog.Logger { + l, _ := ctx.Value(loggerKey).(*slog.Logger) + if l == nil { + l = slog.Default() + } + + var attrs []any + + if tid := tenant.FromContext(ctx); tid != "" && tid != "default" { + attrs = append(attrs, slog.String("tenant_id", tid)) + } + if traceID := TraceIDFromContext(ctx); traceID != "" { + attrs = append(attrs, slog.String("trace_id", traceID)) + } + + if len(attrs) > 0 { + return l.With(attrs...) + } + return l +} + +// WithTraceID stores traceID in ctx so that subsequent calls to FromContext +// will automatically include it in every log record. The gateway sets this +// from the incoming X-Trace-ID header; downstream services propagate it +// by forwarding the header on outgoing calls. +func WithTraceID(ctx context.Context, traceID string) context.Context { + return context.WithValue(ctx, traceIDKey, traceID) +} + +// TraceIDFromContext returns the trace ID stored by WithTraceID, or empty +// string if none was set. +func TraceIDFromContext(ctx context.Context) string { + if v, ok := ctx.Value(traceIDKey).(string); ok { + return v + } + return "" +} + +// ─── HTTP middleware ─────────────────────────────────────────────────────────── + +// HTTPMiddleware returns an http.Handler middleware that: +// +// 1. Extracts (or notes the absence of) a trace ID from the X-Trace-ID or +// X-Request-ID request header. +// 2. Stores the service logger and trace ID in the request context so that +// handler code can call FromContext to obtain a pre-enriched logger. +// 3. After the handler returns, emits a single INFO-level "http request" +// record containing: method, path, status, latency, remote_addr, +// tenant_id (when present), trace_id (when present). +// +// Chain this after the tenant.Middleware so that tenant_id is available: +// +// http.ListenAndServe(addr, tenant.Middleware(logger.HTTPMiddleware(log)(mux))) +func HTTPMiddleware(l *slog.Logger) func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + + // Prefer X-Trace-ID; fall back to X-Request-ID for compatibility + // with AWS ALB / GCP load balancers that inject X-Request-ID. + traceID := r.Header.Get("X-Trace-ID") + if traceID == "" { + traceID = r.Header.Get("X-Request-ID") + } + + ctx := r.Context() + ctx = WithContext(ctx, l) + if traceID != "" { + ctx = WithTraceID(ctx, traceID) + } + + // Wrap the ResponseWriter so we can capture the status code written + // by the handler without interfering with its normal operation. + rw := &statusRecorder{ResponseWriter: w, status: http.StatusOK} + next.ServeHTTP(rw, r.WithContext(ctx)) + + attrs := []any{ + slog.String("method", r.Method), + slog.String("path", r.URL.Path), + slog.Int("status", rw.status), + slog.Duration("latency", time.Since(start)), + slog.String("remote_addr", r.RemoteAddr), + } + if tid := tenant.FromContext(ctx); tid != "" && tid != "default" { + attrs = append(attrs, slog.String("tenant_id", tid)) + } + if traceID != "" { + attrs = append(attrs, slog.String("trace_id", traceID)) + } + + l.InfoContext(ctx, "http request", attrs...) + }) + } +} + +// ─── internal helpers ───────────────────────────────────────────────────────── + +// statusRecorder wraps http.ResponseWriter to capture the HTTP status code. +// The zero value's status field must be initialised to 200 before use. +type statusRecorder struct { + http.ResponseWriter + status int + wroteHeader bool +} + +func (r *statusRecorder) WriteHeader(code int) { + if r.wroteHeader { + return + } + r.status = code + r.wroteHeader = true + r.ResponseWriter.WriteHeader(code) +} + +func (r *statusRecorder) Write(b []byte) (int, error) { + if !r.wroteHeader { + r.WriteHeader(http.StatusOK) + } + return r.ResponseWriter.Write(b) +} + +// Unwrap allows net/http internals (e.g. http.Flusher, http.Hijacker) to reach +// the underlying ResponseWriter through the wrapper. +func (r *statusRecorder) Unwrap() http.ResponseWriter { + return r.ResponseWriter +} + +// parseLevel converts a string level to slog.Level. +// Unknown / empty values default to slog.LevelInfo. +func parseLevel(s string) slog.Level { + switch strings.ToLower(s) { + case "debug": + return slog.LevelDebug + case "warn", "warning": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} diff --git a/packages/go-common/logger/logger_test.go b/packages/go-common/logger/logger_test.go new file mode 100644 index 0000000..9a5c895 --- /dev/null +++ b/packages/go-common/logger/logger_test.go @@ -0,0 +1,273 @@ +/* + * Copyright (c) 2026, SoftlaneIT (https://softlaneit.com/) All Rights Reserved. + * + * SoftlaneIT licenses this file to you under the Apache License, + * Version 2.0 (the "LICENSE"); you may not use this file except + * in compliance with the LICENSE. + * You may obtain a copy of the LICENSE at + * + * https://softlaneit.com/LICENSE.txt + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the LICENSE is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the LICENSE for the + * specific language governing permissions and limitations + * under the LICENSE. + */ + +package logger_test + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/SoftLaneIT/serviceforge/packages/go-common/logger" + "github.com/SoftLaneIT/serviceforge/packages/go-common/tenant" +) + +// newBufLogger builds a JSON logger that writes to buf instead of os.Stdout. +// This lets tests inspect the exact bytes emitted without capturing stdout. +func newBufLogger(buf *bytes.Buffer, level slog.Level) *slog.Logger { + h := slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: level}) + return slog.New(h) +} + +// decodeLastRecord unmarshals the last newline-delimited JSON object in buf. +func decodeLastRecord(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + lines := strings.Split(strings.TrimSpace(buf.String()), "\n") + var rec map[string]any + if err := json.Unmarshal([]byte(lines[len(lines)-1]), &rec); err != nil { + t.Fatalf("failed to decode log record: %v\nraw: %s", err, buf.String()) + } + return rec +} + +// ─── parseLevel ─────────────────────────────────────────────────────────────── + +func TestNew_LevelDebug(t *testing.T) { + var buf bytes.Buffer + // We can't swap os.Stdout, so we verify via the exported Options struct + // that constructing a logger with level "debug" does not panic and that + // the returned logger accepts debug records. + h := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}) + l := slog.New(h) + l.Debug("debug message") + + if !strings.Contains(buf.String(), "debug message") { + t.Fatalf("expected debug message in output, got: %s", buf.String()) + } +} + +func TestNew_LevelInfo_FiltersDebug(t *testing.T) { + var buf bytes.Buffer + h := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}) + l := slog.New(h) + l.Debug("should be dropped") + l.Info("should appear") + + output := buf.String() + if strings.Contains(output, "should be dropped") { + t.Fatal("debug record should have been filtered at info level") + } + if !strings.Contains(output, "should appear") { + t.Fatal("info record was unexpectedly filtered") + } +} + +// ─── context helpers ────────────────────────────────────────────────────────── + +func TestWithContext_FromContext_ReturnsStoredLogger(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + ctx := logger.WithContext(context.Background(), l) + got := logger.FromContext(ctx) + + got.Info("hello from context") + if !strings.Contains(buf.String(), "hello from context") { + t.Fatalf("expected log output from context logger, got: %s", buf.String()) + } +} + +func TestFromContext_FallsBackToDefault(t *testing.T) { + // No logger stored — should not panic and should return a non-nil logger. + got := logger.FromContext(context.Background()) + if got == nil { + t.Fatal("FromContext returned nil without a stored logger") + } +} + +func TestFromContext_EnrichesWithTenantID(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + // Build a context that carries a tenant ID (via the tenant package) and a + // stored logger. + req := httptest.NewRequest(http.MethodGet, "/", nil) + req.Header.Set("X-Tenant-ID", "acme-corp") + + // Use the tenant middleware to inject the tenant ID into the context. + var capturedCtx context.Context + handler := tenant.Middleware(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + capturedCtx = r.Context() + })) + handler.ServeHTTP(httptest.NewRecorder(), req) + + enrichedCtx := logger.WithContext(capturedCtx, l) + log := logger.FromContext(enrichedCtx) + log.Info("tenant-aware record") + + rec := decodeLastRecord(t, &buf) + if rec["tenant_id"] != "acme-corp" { + t.Fatalf("expected tenant_id=acme-corp, got: %v", rec["tenant_id"]) + } +} + +func TestFromContext_EnrichesWithTraceID(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + ctx := logger.WithContext(context.Background(), l) + ctx = logger.WithTraceID(ctx, "trace-xyz-123") + + logger.FromContext(ctx).Info("traced record") + + rec := decodeLastRecord(t, &buf) + if rec["trace_id"] != "trace-xyz-123" { + t.Fatalf("expected trace_id=trace-xyz-123, got: %v", rec["trace_id"]) + } +} + +func TestFromContext_DoesNotAppendDefaultTenantID(t *testing.T) { + // The "default" fallback tenant should not pollute log records. + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + ctx := logger.WithContext(context.Background(), l) + logger.FromContext(ctx).Info("no-tenant record") + + rec := decodeLastRecord(t, &buf) + if _, ok := rec["tenant_id"]; ok { + t.Fatalf("tenant_id should not appear for default tenant, got: %v", rec["tenant_id"]) + } +} + +func TestWithTraceID_TraceIDFromContext(t *testing.T) { + ctx := logger.WithTraceID(context.Background(), "req-abc") + if got := logger.TraceIDFromContext(ctx); got != "req-abc" { + t.Fatalf("expected req-abc, got %q", got) + } +} + +func TestTraceIDFromContext_EmptyWhenNotSet(t *testing.T) { + if got := logger.TraceIDFromContext(context.Background()); got != "" { + t.Fatalf("expected empty string, got %q", got) + } +} + +// ─── HTTPMiddleware ─────────────────────────────────────────────────────────── + +func TestHTTPMiddleware_LogsRequest(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + mux := http.NewServeMux() + mux.HandleFunc("/ping", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + // Chain: tenant middleware → logger middleware → mux. + handler := tenant.Middleware(logger.HTTPMiddleware(l)(mux)) + + req := httptest.NewRequest(http.MethodGet, "/ping", nil) + req.Header.Set("X-Tenant-ID", "test-tenant") + req.Header.Set("X-Trace-ID", "trace-001") + + rw := httptest.NewRecorder() + handler.ServeHTTP(rw, req) + + rec := decodeLastRecord(t, &buf) + + checks := map[string]any{ + "msg": "http request", + "method": "GET", + "path": "/ping", + "status": float64(http.StatusOK), + "tenant_id": "test-tenant", + "trace_id": "trace-001", + } + for field, want := range checks { + if rec[field] != want { + t.Errorf("field %q: want %v, got %v", field, want, rec[field]) + } + } + if _, ok := rec["latency"]; !ok { + t.Error("expected latency field in log record") + } +} + +func TestHTTPMiddleware_CapturesNon200Status(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + mux := http.NewServeMux() + mux.HandleFunc("/boom", func(w http.ResponseWriter, _ *http.Request) { + http.Error(w, "not found", http.StatusNotFound) + }) + + handler := logger.HTTPMiddleware(l)(mux) + req := httptest.NewRequest(http.MethodGet, "/boom", nil) + handler.ServeHTTP(httptest.NewRecorder(), req) + + rec := decodeLastRecord(t, &buf) + if rec["status"] != float64(http.StatusNotFound) { + t.Fatalf("expected status 404, got %v", rec["status"]) + } +} + +func TestHTTPMiddleware_XRequestIDFallback(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + mux := http.NewServeMux() + mux.HandleFunc("/", func(w http.ResponseWriter, _ *http.Request) {}) + + handler := logger.HTTPMiddleware(l)(mux) + req := httptest.NewRequest(http.MethodGet, "/", nil) + req.Header.Set("X-Request-ID", "req-fallback-99") + + handler.ServeHTTP(httptest.NewRecorder(), req) + + rec := decodeLastRecord(t, &buf) + if rec["trace_id"] != "req-fallback-99" { + t.Fatalf("expected trace_id from X-Request-ID, got %v", rec["trace_id"]) + } +} + +func TestHTTPMiddleware_StoresLoggerInContext(t *testing.T) { + var buf bytes.Buffer + l := newBufLogger(&buf, slog.LevelInfo) + + mux := http.NewServeMux() + mux.HandleFunc("/ctx", func(w http.ResponseWriter, r *http.Request) { + // Handler uses FromContext — this must write to buf, not /dev/null. + logger.FromContext(r.Context()).Info("inside handler") + w.WriteHeader(http.StatusOK) + }) + + handler := logger.HTTPMiddleware(l)(mux) + req := httptest.NewRequest(http.MethodGet, "/ctx", nil) + handler.ServeHTTP(httptest.NewRecorder(), req) + + if !strings.Contains(buf.String(), "inside handler") { + t.Fatalf("handler logger did not write to the expected buffer: %s", buf.String()) + } +}