diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index aac1f927..f96d7c63 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -66,7 +66,7 @@ hyperfleet-api/ │ ├── db/ # Database session factory, migrations, transaction middleware │ ├── errors/ # RFC 9457 Problem Details error model │ ├── handlers/ # HTTP handler pattern, validation and error handling -│ ├── logger/ # Structured logging (slog-based) +│ ├── logger/ # API logging integration (request ID, HTTP attrs, GORM adapter) │ ├── presenters/ # Response presenters (DAO models → API responses) │ └── services/ # Business logic layer (status aggregation, validation) ├── openapi/ # API specification source diff --git a/cmd/hyperfleet-api/container/validation.go b/cmd/hyperfleet-api/container/validation.go index fb9b0dbb..26b6ca84 100644 --- a/cmd/hyperfleet-api/container/validation.go +++ b/cmd/hyperfleet-api/container/validation.go @@ -3,6 +3,7 @@ package container import ( "context" "fmt" + "log/slog" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/validators" @@ -16,7 +17,7 @@ func (c *Container) SchemaValidator() *validators.SchemaValidator { panic(fmt.Sprintf("create schema validator: %v", err)) } c.schemaValidator = schemaValidator - logger.With(context.Background(), logger.FieldSchemaPath, schemaPath).Info("Schema validation enabled") + slog.InfoContext(context.Background(), "Schema validation enabled", logger.FieldSchemaPath, schemaPath) } return c.schemaValidator } diff --git a/cmd/hyperfleet-api/main.go b/cmd/hyperfleet-api/main.go index 88d73edf..94d45312 100755 --- a/cmd/hyperfleet-api/main.go +++ b/cmd/hyperfleet-api/main.go @@ -7,6 +7,7 @@ import ( "log/slog" "os" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "github.com/spf13/cobra" "github.com/openshift-hyperfleet/hyperfleet-api/cmd/hyperfleet-api/migrate" @@ -36,27 +37,27 @@ func main() { rootCmd.AddCommand(migrateCmd, serveCmd, versionCmd) if err := rootCmd.Execute(); err != nil { - logger.WithError(ctx, err).Error("Error running command") + slog.ErrorContext(ctx, "Error running command", "error", err) os.Exit(1) } } // initDefaultLogger initializes a default logger with INFO level // This ensures logging works before environment/config is loaded -// Reads HYPERFLEET_LOGGING_* from environment variables if set +// Reads HYPERFLEET_LOGGING_* variables if set. func initDefaultLogger() { // Read log level from environment with default fallback level := slog.LevelInfo if levelStr := os.Getenv("HYPERFLEET_LOGGING_LEVEL"); levelStr != "" { - if parsed, err := logger.ParseLogLevel(levelStr); err == nil { + if parsed, err := hfl.ParseLevel(levelStr); err == nil { level = parsed } } // Read log format from environment with default fallback - format := logger.FormatJSON + format := hfl.FormatJSON if formatStr := os.Getenv("HYPERFLEET_LOGGING_FORMAT"); formatStr != "" { - if parsed, err := logger.ParseLogFormat(formatStr); err == nil { + if parsed, err := hfl.ParseFormat(formatStr); err == nil { format = parsed } } @@ -64,28 +65,14 @@ func initDefaultLogger() { // Read log output from environment with default fallback var output io.Writer = os.Stdout if outputStr := os.Getenv("HYPERFLEET_LOGGING_OUTPUT"); outputStr != "" { - if parsed, err := logger.ParseLogOutput(outputStr); err == nil { + if parsed, err := hfl.ParseOutput(outputStr); err == nil { output = parsed } } - cfg := &logger.LogConfig{ - Level: level, - Format: format, - Output: output, - Component: "hyperfleet-api", - Version: api.Version, - Hostname: getHostname(), - } - logger.InitGlobalLogger(cfg) -} - -func getHostname() string { - hostname, err := os.Hostname() - if err != nil { - return "unknown" - } - return hostname + slog.SetDefault(logger.NewLogger(api.Version, logger.HandlerConfig{ + Level: level, Format: format, Output: output, + })) } func newVersionCommand() *cobra.Command { diff --git a/cmd/hyperfleet-api/migrate/cmd.go b/cmd/hyperfleet-api/migrate/cmd.go index 56bfee09..bb7ec064 100755 --- a/cmd/hyperfleet-api/migrate/cmd.go +++ b/cmd/hyperfleet-api/migrate/cmd.go @@ -2,10 +2,13 @@ package migrate import ( "context" + "log/slog" "os" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "github.com/spf13/cobra" + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/config" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db/db_session" @@ -40,9 +43,10 @@ func runMigrate(cmd *cobra.Command, _ []string) { loader := config.NewConfigLoader() appConfig, err := loader.Load(ctx, cmd) if err != nil { - logger.WithError(ctx, err).Error("Failed to load configuration") + slog.ErrorContext(ctx, "Failed to load configuration", "error", err) os.Exit(1) } + initLogger(appConfig.Logging) // Run migration with the loaded configuration if err := runMigrateWithError(ctx, appConfig.Database); err != nil { @@ -50,17 +54,35 @@ func runMigrate(cmd *cobra.Command, _ []string) { } } +func initLogger(loggingCfg *config.LoggingConfig) { + level, err := hfl.ParseLevel(loggingCfg.Level) + if err != nil { + level = slog.LevelInfo + } + format, err := hfl.ParseFormat(loggingCfg.Format) + if err != nil { + format = hfl.FormatJSON + } + output, err := hfl.ParseOutput(loggingCfg.Output) + if err != nil { + output = os.Stdout + } + slog.SetDefault(logger.NewLogger(api.Version, logger.HandlerConfig{ + Level: level, Format: format, Output: output, + })) +} + func runMigrateWithError(ctx context.Context, dbConfig *config.DatabaseConfig) error { connection := db_session.NewProdFactory(dbConfig) defer func() { if closeErr := connection.Close(); closeErr != nil { - logger.WithError(ctx, closeErr).Error("Failed to close database connection") + slog.ErrorContext(ctx, "Failed to close database connection", "error", closeErr) } }() // Use MigrateWithLock to prevent concurrent migrations from multiple pods if err := db.MigrateWithLock(ctx, connection); err != nil { - logger.WithError(ctx, err).Error("Migration failed") + slog.ErrorContext(ctx, "Migration failed", "error", err) return err } diff --git a/cmd/hyperfleet-api/servecmd/cmd.go b/cmd/hyperfleet-api/servecmd/cmd.go index 34801177..91956519 100755 --- a/cmd/hyperfleet-api/servecmd/cmd.go +++ b/cmd/hyperfleet-api/servecmd/cmd.go @@ -11,6 +11,7 @@ import ( "syscall" "time" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "github.com/spf13/cobra" "github.com/openshift-hyperfleet/hyperfleet-api/cmd/hyperfleet-api/container" @@ -57,8 +58,9 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { // container.Container's accessors panic by design; log the stack here since main.go can't see it. defer func() { if r := recover(); r != nil { - logger.With(context.Background(), "panic_stack", string(debug.Stack())). - Error(fmt.Sprintf("recovered from panic in runServe: %v", r)) + slog.ErrorContext(context.Background(), + fmt.Sprintf("recovered from panic in runServe: %v", r), "panic_stack", string(debug.Stack()), + ) runErr = fmt.Errorf("%v", r) } }() @@ -82,27 +84,27 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { closeErr := c.Close() runErr = errors.Join(runErr, closeErr) if runErr == nil { - logger.Info(context.Background(), "Graceful shutdown completed") + slog.InfoContext(context.Background(), "Graceful shutdown completed") } }() - ctr := container.NewContainer(cfg, c) - initLogger(cfg) + ctr := container.NewContainer(cfg, c) + sf := ctr.SessionFactory() configureDBLogger(cfg, sf) - logger.Info(ctx, "Starting HyperFleet API with configuration (sensitive values redacted):") - logger.Info(ctx, config.DumpConfig(cfg)) + slog.InfoContext(ctx, "Starting HyperFleet API with configuration (sensitive values redacted):") + slog.InfoContext(ctx, config.DumpConfig(cfg)) // OTel registered first so it flushes last - teardown spans are preserved. if cfg.Tracing.Enabled { traceProvider, traceErr := telemetry.InitTraceProvider(ctx, cfg.Tracing.ServiceName, api.Version) if traceErr != nil { - logger.WithError(ctx, traceErr).Warn("Failed to initialize OpenTelemetry") + slog.WarnContext(ctx, "Failed to initialize OpenTelemetry", "error", traceErr) } else { - logger.With(ctx, logger.FieldServiceName, cfg.Tracing.ServiceName).Info("OpenTelemetry initialized") + slog.InfoContext(ctx, "OpenTelemetry initialized", logger.FieldServiceName, cfg.Tracing.ServiceName) c.Add(func() error { flushCtx, cancel := context.WithTimeout(context.Background(), otelFlushTimeout) defer cancel() @@ -110,21 +112,20 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { }) } } else { - logger.With(ctx, logger.FieldOTelEnabled, false).Info("OpenTelemetry disabled") + slog.InfoContext(ctx, "OpenTelemetry disabled", logger.FieldOTelEnabled, false) } - - logger.With(ctx, - "log_level", cfg.Logging.Level, + slog.InfoContext(ctx, + "Logger initialized", "log_level", cfg.Logging.Level, "log_format", cfg.Logging.Format, "log_output", cfg.Logging.Output, "masking_enabled", cfg.Logging.Masking.Enabled, - ).Info("Logger initialized") + ) if collectorErr := metrics.RegisterReconciliationCollector( ctr.SessionFactory().DirectDB(), cfg.Metrics.ReconciliationStuckThreshold, ); collectorErr != nil { - logger.WithError(ctx, collectorErr).Error("Failed to register reconciliation collector") + slog.ErrorContext(ctx, "Failed to register reconciliation collector", "error", collectorErr) } apiServer, err := BuildAPIServer( @@ -150,7 +151,7 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { // Readyz registered last so it runs first - immediately fails the probe. c.Add(func() error { health.GetReadinessState().SetShuttingDown() - logger.Info(context.Background(), "Marked as not ready, draining in-flight requests...") + slog.InfoContext(context.Background(), "Marked as not ready, draining in-flight requests...") return nil }) @@ -190,7 +191,7 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { } if triggerErr == nil && !shutdown { health.GetReadinessState().SetReady() - logger.Info(ctx, "Application ready to receive traffic") + slog.InfoContext(ctx, "Application ready to receive traffic") select { case <-ctx.Done(): case <-signals: @@ -198,7 +199,7 @@ func runServe(cmd *cobra.Command, args []string) (runErr error) { } } - logger.Info(context.Background(), "Shutdown requested, starting graceful shutdown...") + slog.InfoContext(context.Background(), "Shutdown requested, starting graceful shutdown...") runErr = triggerErr return runErr } @@ -218,41 +219,27 @@ func initLogger(cfg *config.ApplicationConfig) { ctx := context.Background() loggingCfg := cfg.Logging - level, err := logger.ParseLogLevel(loggingCfg.Level) + level, err := hfl.ParseLevel(loggingCfg.Level) if err != nil { - logger.With(ctx, logger.FieldLogLevel, loggingCfg.Level).WithError(err).Warn("Invalid log level, using default") + slog.WarnContext(ctx, "Invalid log level, using default", logger.FieldLogLevel, loggingCfg.Level, "error", err) level = slog.LevelInfo } - format, err := logger.ParseLogFormat(loggingCfg.Format) + format, err := hfl.ParseFormat(loggingCfg.Format) if err != nil { - logger.With(ctx, logger.FieldLogFormat, loggingCfg.Format).WithError(err).Warn("Invalid log format, using default") - format = logger.FormatJSON + slog.WarnContext(ctx, "Invalid log format, using default", logger.FieldLogFormat, loggingCfg.Format, "error", err) + format = hfl.FormatJSON } - output, err := logger.ParseLogOutput(loggingCfg.Output) + output, err := hfl.ParseOutput(loggingCfg.Output) if err != nil { - logger.With(ctx, logger.FieldLogOutput, loggingCfg.Output).WithError(err).Warn("Invalid log output, using default") + slog.WarnContext(ctx, "Invalid log output, using default", logger.FieldLogOutput, loggingCfg.Output, "error", err) output = os.Stdout } - hostname := cfg.Server.Hostname - if hostname == "" { - hostname, _ = os.Hostname() //nolint:errcheck // empty string is acceptable fallback - } - - logConfig := &logger.LogConfig{ - Level: level, - Format: format, - Output: output, - Component: "api", - Version: api.Version, - Hostname: hostname, - } - - // Use ReconfigureGlobalLogger instead of InitGlobalLogger because - // InitGlobalLogger was already called in main() with default config - logger.ReconfigureGlobalLogger(logConfig) + slog.SetDefault(logger.NewLogger(api.Version, logger.HandlerConfig{ + Level: level, Format: format, Output: output, + })) } func configureDBLogger(cfg *config.ApplicationConfig, sessionFactory db.SessionFactory) { diff --git a/cmd/hyperfleet-api/server/compress.go b/cmd/hyperfleet-api/server/compress.go index de8147e8..cae760b7 100644 --- a/cmd/hyperfleet-api/server/compress.go +++ b/cmd/hyperfleet-api/server/compress.go @@ -2,11 +2,10 @@ package server import ( "compress/gzip" + "log/slog" "net/http" "strconv" "strings" - - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // gzipResponseWriter wraps an http.ResponseWriter, transparently gzip-encoding @@ -73,7 +72,7 @@ func CompressMiddleware(next http.Handler) http.Handler { gz := gzip.NewWriter(w) defer func() { if err := gz.Close(); err != nil { - logger.WithError(r.Context(), err).Warn("failed to finalize gzip response, response may be incomplete") + slog.WarnContext(r.Context(), "failed to finalize gzip response, response may be incomplete", "error", err) } }() diff --git a/cmd/hyperfleet-api/server/logging/request_logging_middleware.go b/cmd/hyperfleet-api/server/logging/request_logging_middleware.go index 2f0bddf3..59ad62b8 100755 --- a/cmd/hyperfleet-api/server/logging/request_logging_middleware.go +++ b/cmd/hyperfleet-api/server/logging/request_logging_middleware.go @@ -30,14 +30,13 @@ func RequestLoggingMiddleware(masker *middleware.MaskingMiddleware) func(http.Ha } else { maskedHeaders = r.Header } - - logger.With(ctx, - logger.HTTPMethod(r.Method), + slog.InfoContext(ctx, + "HTTP request received", logger.HTTPMethod(r.Method), logger.HTTPPath(r.URL.Path), slog.String("remote_addr", r.RemoteAddr), logger.HTTPUserAgent(r.UserAgent()), slog.Any("headers", maskedHeaders), - ).Info("HTTP request received") + ) rw := &responseWriter{ResponseWriter: w} @@ -48,15 +47,14 @@ func RequestLoggingMiddleware(masker *middleware.MaskingMiddleware) func(http.Ha if rw.statusCode == 0 { rw.statusCode = http.StatusOK } - - logger.With(ctx, - logger.HTTPMethod(r.Method), + slog.InfoContext(ctx, + "HTTP request completed", logger.HTTPMethod(r.Method), logger.HTTPPath(r.URL.Path), logger.HTTPStatusCode(rw.statusCode), logger.HTTPDuration(duration), slog.String("remote_addr", r.RemoteAddr), logger.HTTPUserAgent(r.UserAgent()), - ).Info("HTTP request completed") + ) }) } } diff --git a/cmd/hyperfleet-api/server/server.go b/cmd/hyperfleet-api/server/server.go index 27a22dcb..60d73ec2 100755 --- a/cmd/hyperfleet-api/server/server.go +++ b/cmd/hyperfleet-api/server/server.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "errors" "fmt" + "log/slog" "net" "net/http" "strings" @@ -48,16 +49,16 @@ func (s *baseServer) Serve(listener net.Listener) error { return errors.Join(configErr, listener.Close()) } - logger.With(ctx, logger.FieldBindAddress, s.httpServer.Addr).Info("Serving " + s.name + " with TLS") + slog.InfoContext(ctx, "Serving "+s.name+" with TLS", logger.FieldBindAddress, s.httpServer.Addr) err = s.httpServer.ServeTLS(listener, s.cfg.TLSCertFile(), s.cfg.TLSKeyFile()) } else { - logger.With(ctx, logger.FieldBindAddress, s.httpServer.Addr).Info("Serving " + s.name + " without TLS") + slog.InfoContext(ctx, "Serving "+s.name+" without TLS", logger.FieldBindAddress, s.httpServer.Addr) err = s.httpServer.Serve(listener) } if err != nil && !errors.Is(err, http.ErrServerClosed) { return fmt.Errorf("%s terminated with errors: %w", s.name, err) } - logger.Info(ctx, s.name+" terminated") + slog.InfoContext(ctx, s.name+" terminated") return nil } diff --git a/docs/config.md b/docs/config.md index 5978d59b..1a8cc674 100644 --- a/docs/config.md +++ b/docs/config.md @@ -175,8 +175,8 @@ Logging behavior and output settings. | `logging.level` | string | `info` | Log level: `debug`, `info`, `warn`, `error` | | `logging.format` | string | `json` | Log format: `json`, `text` | | `logging.output` | string | `stdout` | Log output: `stdout`, `stderr` | -| `logging.otel.enabled` | bool | `true` | Enable OpenTelemetry tracing (see [OpenTelemetry Configuration](#opentelemetry-configuration)) | -| `logging.masking.enabled` | bool | `true` | Enable sensitive data masking in logs | +| `logging.otel.enabled` (deprecated) | bool | `true` | Legacy OpenTelemetry setting; `tracing.enabled` is active and takes precedence when both are configured. If `tracing.enabled` is unset, this setting is used as a fallback. | +| `logging.masking.enabled` | bool | `true` | Enable sensitive request-header masking in logs | **Example:** @@ -203,7 +203,7 @@ OpenTelemetry tracing is configured via standard environment variables following | Property | Environment Variable | Type | Default | Description | |----------|---------------------|------|---------|-------------| -| `logging.otel.enabled` | `HYPERFLEET_TRACING_ENABLED` | bool | `true` | Enable OpenTelemetry tracing (HyperFleet standard) | +| `tracing.enabled` | `HYPERFLEET_TRACING_ENABLED` | bool | `true` | Enable OpenTelemetry tracing (active setting; takes precedence over deprecated `logging.otel.enabled`) | **Standard OpenTelemetry Environment Variables:** @@ -477,7 +477,8 @@ Complete table of all configuration properties, their environment variables, and | `logging.level` | `HYPERFLEET_LOGGING_LEVEL` | string | `info` | | `logging.format` | `HYPERFLEET_LOGGING_FORMAT` | string | `json` | | `logging.output` | `HYPERFLEET_LOGGING_OUTPUT` | string | `stdout` | -| `logging.otel.enabled` | `HYPERFLEET_TRACING_ENABLED` | bool | `true` | +| `logging.otel.enabled` (deprecated) | `HYPERFLEET_TRACING_ENABLED` | bool | `true` | +| `tracing.enabled` | `HYPERFLEET_TRACING_ENABLED` | bool | `true` | | `logging.masking.enabled` | `HYPERFLEET_LOGGING_MASKING_ENABLED` | bool | `true` | | `logging.masking.headers` | `HYPERFLEET_LOGGING_MASKING_HEADERS` | csv | `Authorization,Cookie` | | `logging.masking.fields` | `HYPERFLEET_LOGGING_MASKING_FIELDS` | csv | `password,token` | diff --git a/docs/logging.md b/docs/logging.md index 5618dcae..f6ae56bc 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -1,537 +1,497 @@ # HyperFleet API Logging -This document describes the logging system used in hyperfleet-api. - -## Overview - -HyperFleet API uses Go's standard library `log/slog` for structured logging with the following features: - -- **Structured logging**: All logs use key-value pairs for better queryability -- **Context-aware logging**: Automatic request_id, trace_id, and span_id propagation -- **Data masking**: Sensitive data redaction in headers and JSON payloads -- **OpenTelemetry integration**: Distributed tracing with configurable sampling -- **JSON and text output**: Machine-parseable JSON or human-readable text format -- **Custom handler**: Automatic component, version, and hostname fields +HyperFleet API uses Go's `log/slog` for structured, context-aware logging. The +shared [`hyperfleet-logger`](https://github.com/openshift-hyperfleet/hyperfleet-logger) +module owns JSON and text formatting, standard fields, context extraction, +control-character sanitization, and stack capture. This repository owns the API +integration around that handler: request IDs, HTTP attributes, request-header +masking, the GORM adapter, and the API's stack-trace policy. + +## Features + +- Structured JSON output for log aggregation and human-readable text output for + local development +- A consistent `component=api`, application version, and OS/pod hostname on + every record +- Request, trace, span, and resource correlation through `context.Context` +- UUIDv7 request IDs returned in the `X-Request-ID` response header +- Sensitive request-header redaction with a configurable header list +- OpenTelemetry trace propagation and configurable export and sampling +- GORM query, slow-query, and error records using the same logger +- Automatic stack traces on JSON error records, matching the previous JSON logger ## Architecture -### Components +The relevant components are: -1. **pkg/logger/logger.go**: Core logger with HyperFleetHandler (custom slog.Handler) -2. **pkg/logger/context.go**: Context key definitions for trace_id, span_id, cluster_id, etc. -3. **pkg/logger/requestid_middleware.go**: Request ID generation and middleware -4. **pkg/middleware/otel.go**: OpenTelemetry trace context extraction -5. **pkg/telemetry/otel.go**: OpenTelemetry trace provider initialization +| Component | Responsibility | +| --- | --- | +| `pkg/logger/handler.go` | Builds the API logger around `hyperfleet-logger`; defines component identity, sanitization, and stack policy | +| `pkg/logger/context.go` | Defines the API-owned `request_id` context field | +| `pkg/logger/requestid_middleware.go` | Generates request IDs and sets `X-Request-ID` | +| `pkg/logger/http.go` | Provides typed `slog.Attr` helpers for HTTP fields | +| `pkg/logger/gorm_logger.go` | Adapts GORM logging to `slog` | +| `pkg/middleware/otel.go` | Creates/continues HTTP spans and adds trace/span IDs to log context | +| `pkg/middleware/masking.go` | Redacts configured request headers | +| `cmd/hyperfleet-api/server/logging/request_logging_middleware.go` | Emits request-start and request-completion records | +| `pkg/telemetry/otel.go` | Configures the OpenTelemetry provider, exporter, sampler, and propagators | -### Middleware Chain +The main API middleware is applied in this order: ```text -HTTP Request - ↓ -RequestIDMiddleware (adds request_id to context) - ↓ -OTelMiddleware (extracts trace_id and span_id, optional) - ↓ -RequestLoggingMiddleware (logs request/response with masking) - ↓ -Handler (business logic) +HTTP request + -> RequestIDMiddleware + -> OTelMiddleware (when tracing is enabled) + -> RequestLoggingMiddleware + -> API/auth/validation/transaction middleware + -> Handler -> Service -> DAO ``` -## Configuration +This order makes the request and trace identifiers available to request logs and +all downstream `slog.*Context` calls. -Logging is configured through environment variables or configuration files. +## Configuration -**Development:** -```bash -# Human-readable text format with debug level -export HYPERFLEET_LOGGING_FORMAT=text -export HYPERFLEET_LOGGING_LEVEL=debug -``` +Application configuration uses this precedence, from highest to lowest: -**Production:** -```bash -# Structured JSON format with info level -export HYPERFLEET_LOGGING_FORMAT=json -export HYPERFLEET_LOGGING_LEVEL=info +1. CLI flag +2. Environment variable +3. Configuration file +4. Default -# OpenTelemetry tracing (Tracing standard) -export HYPERFLEET_TRACING_ENABLED=true -export OTEL_TRACES_SAMPLER=parentbased_traceidratio -export OTEL_TRACES_SAMPLER_ARG=0.1 -export OTEL_EXPORTER_OTLP_ENDPOINT=http://otel-collector:4317 -``` +### Logging settings -**For complete configuration reference**, including all logging settings (levels, formats, OpenTelemetry, masking), see: -- **[Configuration Guide](config.md)** - All logging environment variables and defaults +| Setting | CLI flag | Environment variable | Default | +| --- | --- | --- | --- | +| Level | `--log-level`, `-l` | `HYPERFLEET_LOGGING_LEVEL` | `info` | +| Format | `--log-format`, `-f` | `HYPERFLEET_LOGGING_FORMAT` | `json` | +| Output | `--log-output` | `HYPERFLEET_LOGGING_OUTPUT` | `stdout` | +| Masking enabled | `--log-masking-enabled` | `HYPERFLEET_LOGGING_MASKING_ENABLED` | `true` | +| Sensitive headers | `--log-masking-sensitive-headers` | `HYPERFLEET_LOGGING_MASKING_HEADERS` | See [Data masking](#data-masking) | -### OpenTelemetry Environment Variables +Valid levels are `debug`, `info`, `warn`, and `error`. Valid formats are `json` +and `text`; valid outputs are `stdout` and `stderr`. -HyperFleet uses standard OpenTelemetry environment variables for tracing configuration: +For local development: -| Variable | Description | Default | Example | -|----------|-------------|---------|---------| -| `HYPERFLEET_TRACING_ENABLED` | Enable/disable tracing (Tracing standard, overrides config) | `true` (config fallback) | `true`, `false` | -| `OTEL_SERVICE_NAME` | Service name in traces | `hyperfleet-api` | `hyperfleet-api-prod` | -| `OTEL_EXPORTER_OTLP_ENDPOINT` | OTLP collector endpoint (if not set, uses stdout) | - | `http://otel-collector:4317` | -| `OTEL_EXPORTER_OTLP_PROTOCOL` | OTLP protocol | `grpc` | `grpc`, `http/protobuf` | -| `OTEL_TRACES_SAMPLER` | Sampler type | `parentbased_always_on` | `always_on`, `traceidratio` | -| `OTEL_TRACES_SAMPLER_ARG` | Argument passed to the sampler | - | `0.1` (10%) | -| `OTEL_RESOURCE_ATTRIBUTES` | Additional resource attributes | - | `env=prod,region=us-east` | +```bash +HYPERFLEET_LOGGING_LEVEL=debug \ +HYPERFLEET_LOGGING_FORMAT=text \ +./bin/hyperfleet-api serve +``` -**Variable Precedence (highest to lowest):** -1. `HYPERFLEET_TRACING_ENABLED` - Tracing standard (env var) -2. `config.yaml: logging.otel.enabled` - Config file -3. Default (`true`) +Equivalent YAML configuration is: + +```yaml +logging: + level: info + format: json + output: stdout + masking: + enabled: true + headers: + - Authorization + - X-API-Key + - Cookie +``` -## Usage +Both `serve` and `migrate` install the loaded logging level, format, and output. +Before the configuration file is loaded, bootstrap records use the three +`HYPERFLEET_LOGGING_{LEVEL,FORMAT,OUTPUT}` variables, falling back to the normal +defaults. See the [configuration guide](config.md) for the complete application +configuration reference. -### Basic Logging +## Writing application logs -Always use context-aware logging to include automatic fields (request_id, trace_id, span_id): +Use the standard `slog` context methods so correlation fields flow into every +record: ```go import ( - "context" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" -) - -func MyHandler(w http.ResponseWriter, r *http.Request) { - ctx := r.Context() + "context" + "log/slog" - // Simple log (context fields only) - logger.Info(ctx, "Processing cluster creation") + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" - // Log with temporary fields using With() - logger.With(ctx, "cluster_id", clusterID, "region", region).Info("Cluster created") - - // Error level (automatically includes stack trace) - logger.With(ctx, "host", "localhost").WithError(err).Error("Database connection failed") + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" +) - // Debug level - logger.With(ctx, "key", "cluster:123").Debug("Cache hit") +func updateResource(ctx context.Context, kind, id, adapter string) { + ctx = hfl.WithResourceType(ctx, kind) + ctx = hfl.WithResourceID(ctx, id) + ctx = logger.WithAdapter(ctx, adapter) - // Warning level - logger.With(ctx, "used_mb", 1024, "threshold_mb", 800).Warn("High memory usage") + slog.DebugContext(ctx, "Preparing resource update") + slog.InfoContext(ctx, "Resource updated") } ``` -Logs automatically include: -- `component`: "hyperfleet-api" -- `version`: Application version -- `hostname`: Pod/host name -- `request_id`: Unique request identifier -- `trace_id`: W3C trace ID (when OTel enabled) -- `span_id`: Current span ID (when OTel enabled) - -### Available Functions +Derive a child context from the one received by the handler or service. Do not +replace it with `context.Background()`, because that discards request and trace +correlation. For recursive or batched work, derive a separate resource context +for each item so identifiers do not leak into sibling operations. + +Use levels consistently: + +- `DEBUG`: diagnostic detail normally disabled in production +- `INFO`: normal lifecycle events and handled client responses +- `WARN`: degraded behavior, retryable problems, slow queries, and fallbacks +- `ERROR`: server-side failures requiring attention + +### Automatic fields + +| Field | Source | When present | +| --- | --- | --- | +| `timestamp` | Shared handler | Every record | +| `level` | `slog.Record` | Every record | +| `message` | `slog.Record` | Every record | +| `component` | API handler factory | Every record; always `api` | +| `version` | Build metadata | Every record | +| `hostname` | `os.Hostname()` through the shared handler | Every record; `unknown` if discovery fails | +| `request_id` | API request-ID middleware | HTTP request and downstream records | +| `trace_id`, `span_id` | OpenTelemetry middleware | Traced HTTP request and downstream records | +| `resource_type`, `resource_id` | Shared context helpers | Operations whose service context has been enriched with a known resource | +| `adapter` | `logger.WithAdapter` | Adapter report processing, including validation, persistence, and aggregation | + +`server.hostname` is the public server name and does not override the logging +hostname. + +The HTTP status handlers derive a child context with the incoming adapter name +after decoding and validating the report, and pass it through conversion, +service calls, presentation, and error handling. +Concurrent reports retain their own `adapter` and `request_id` fields without +changing the caller's context. When aggregation inspects another adapter's +report, its diagnostic log derives a context with that adapter's name. + +`RequestIDMiddleware` generates a UUIDv7 when its incoming context does not +already contain the API request-ID key. It preserves a request ID already placed +in that context and returns the selected value in `X-Request-ID`. It does not +trust an arbitrary inbound `X-Request-ID` header as the request ID. + +### Temporary fields and helpers + +Use structured attributes for values scoped to one record. Prefer constants +from `pkg/logger/fields.go` and HTTP helpers from `pkg/logger/http.go` when a +field is already defined: ```go -// Simple logging (context fields only) -logger.Info(ctx, "message") -logger.Warn(ctx, "message") -logger.Error(ctx, "message") -logger.Debug(ctx, "message") - -// Logging with temporary fields (use With()) -logger.With(ctx, "key", "value").Info("message") -logger.With(ctx, "key1", value1, "key2", value2).Error("message") - -// Logging with errors (use WithError()) -logger.WithError(ctx, err).Error("Operation failed") -logger.With(ctx, "host", "localhost").WithError(err).Error("Connection failed") - -// Chaining multiple With() calls -logger.With(ctx, "user_id", userID). - With("action", "login"). - WithError(err). - Error("Login failed") - -// Add persistent context fields -ctx = logger.WithClusterID(ctx, "cluster-123") -ctx = logger.WithResourceType(ctx, "managed-cluster") -ctx = logger.WithResourceID(ctx, "resource-456") -``` +slog.InfoContext(ctx, + "HTTP operation completed", + logger.HTTPMethod(r.Method), + logger.HTTPPath(r.URL.Path), + logger.HTTPStatusCode(http.StatusOK), + logger.HTTPDuration(elapsed), +) -### Field Constants +slog.WarnContext(ctx, + "Adapter report was ignored", + logger.FieldAdapter, adapter, + logger.FieldErrorCode, code, +) +``` -Use field constants from `pkg/logger/fields.go` to prevent typos and enable IDE autocomplete: +Do not log passwords, credentials, bearer tokens, raw connection strings, or +complete objects that may contain secrets. Masking the HTTP request log is not a +substitute for selecting safe fields at application call sites. -```go -logger.With(ctx, logger.FieldEnvironment, "production").Info("Environment loaded") -logger.With(ctx, logger.FieldBindAddress, ":8080").Info("Server starting") -logger.With(ctx, logger.FieldConnectionString, sanitized).Info("Database connected") -``` +## Output formats -See `pkg/logger/fields.go` for all available constants (Server/Config, Database, OpenTelemetry, etc.). +### JSON -### HTTP Helper Functions +JSON is the default and is intended for log aggregation. The handler uses +lowercase level names and does not add a `source` field. -Use HTTP helpers from `pkg/logger/http.go` for consistent HTTP field logging: +For this call: ```go -logger.With(r.Context(), - logger.HTTPMethod(r.Method), - logger.HTTPPath(r.URL.Path), - logger.HTTPStatusCode(200), -).Info("Request processed") +slog.InfoContext(ctx, "Resource updated", logger.FieldAdapter, "example") ``` -See `pkg/logger/http.go` for all available helpers (HTTPMethod, HTTPPath, HTTPStatusCode, etc.). - -## Format Comparison - -HyperFleet API supports two log output formats: **JSON** (for production/log aggregation) and **Text** (for development/debugging). - -### JSON Format (`LOG_FORMAT=json`) +a representative record is: -**Characteristics:** -- Machine-parseable structured format -- Ideal for log aggregation systems (Elasticsearch, Splunk, etc.) -- All fields as JSON key-value pairs -- Default format for production deployments - -**Example:** ```json -{"timestamp":"2026-01-09T12:30:45Z","level":"info","message":"Server started","component":"hyperfleet-api","version":"v1.2.3","hostname":"pod-abc","request_id":"2C9zKDz8xQMqF3yH","port":8000} +{"timestamp":"2026-09-14T18:00:00Z","level":"info","message":"Resource updated","component":"api","version":"v1.2.3","hostname":"pod-abc","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","resource_type":"Cluster","resource_id":"cluster-123","request_id":"0199458e-c331-7a22-8443-e25a91e95d81","adapter":"example"} ``` -### Text Format (`LOG_FORMAT=text`) - -**Characteristics:** -- Human-readable format following HyperFleet Logging Specification -- Format: `{timestamp} {LEVEL} [{component}] [{version}] [{hostname}] {message} {key=value}...` -- System fields (`component`, `version`, `hostname`) in brackets for clarity -- Level in uppercase for quick visual scanning -- Ideal for local development and real-time log monitoring +Only context fields actually present on the supplied context are emitted. -**Example:** -```text -2026-01-09T12:30:45Z INFO [hyperfleet-api] [v1.2.3] [pod-abc] Server started request_id=2C9zKDz8xQMqF3yH port=8000 -``` +### Text -### Side-by-Side Comparison +Text output has this shape: -**Same log statement:** -```go -logger.With(ctx, "cluster_id", "cluster-abc123", "region", "us-east-1").Info("Processing cluster creation") +```text +{timestamp} {LEVEL} [{component}] [{version}] [{hostname}] {message} {key=value}... ``` -**JSON output:** -```json -{"timestamp":"2026-01-09T12:30:45Z","level":"info","source":{"function":"main.handler","file":"/app/main.go","line":45},"message":"Processing cluster creation","component":"hyperfleet-api","version":"v1.2.3","hostname":"pod-abc","request_id":"2C9zKDz8xQMqF3yH","cluster_id":"cluster-abc123","region":"us-east-1"} -``` +For example: -**Text output:** ```text -2026-01-09T12:30:45Z INFO [hyperfleet-api] [v1.2.3] [pod-abc] Processing cluster creation request_id=2C9zKDz8xQMqF3yH cluster_id=cluster-abc123 region=us-east-1 +2026-09-14T18:00:00Z INFO [api] [v1.2.3] [pod-abc] Resource updated trace_id=4bf92f3577b34da6a3ce929d0e0e4736 span_id=00f067aa0ba902b7 resource_type=Cluster resource_id=cluster-123 request_id=0199458e-c331-7a22-8443-e25a91e95d81 adapter=example ``` -### Switching Between Formats - -Toggle between formats using the `HYPERFLEET_LOGGING_FORMAT` environment variable (`json` or `text`). No code changes required - the logger automatically adapts output format based on configuration. +The API enables the shared handler's text sanitization. Newlines and other +control characters in messages and attribute values are escaped so +client-controlled values cannot forge additional log lines. -See the [Configuration](#configuration) section above for examples. +## Errors and stack traces -## Database Logging +Stack capture preserves the behavior of the previous API handlers: -HyperFleet API automatically integrates database (GORM) logging with the application's `LOG_LEVEL` configuration while providing a `DB_DEBUG` override for database-specific debugging. +- In JSON format, every emitted record at `ERROR` or above includes `stack_trace`, + regardless of the configured logging level. +- In text format, stack traces are not captured automatically. +- Records below `ERROR` never receive a captured stack trace. Handled HTTP client + failures use `INFO` or `WARN`. -### HYPERFLEET_LOGGING_LEVEL Integration +Log failures with their error value; no additional classification attribute is +required: -Database logs follow the application log level by default: +```go +slog.ErrorContext(ctx, + "Database operation failed", + "error", err, +) +``` -| HYPERFLEET_LOGGING_LEVEL | GORM Behavior | What Gets Logged | -|--------------------------|---------------|------------------| -| `debug` | Info level | All SQL queries with parameters, duration, and row counts | -| `info` | Warn level | Only slow queries (>200ms) and errors | -| `warn` | Warn level | Only slow queries (>200ms) and errors | -| `error` | Silent | Nothing (database logging disabled) | +Recovered startup panics separately include the recovered `panic_stack` captured +by `runtime/debug`, in either format. -### HYPERFLEET_DATABASE_DEBUG Override +## HTTP request logging -The `HYPERFLEET_DATABASE_DEBUG` environment variable provides database-specific debugging without changing the global `HYPERFLEET_LOGGING_LEVEL`: +The request logger emits two `INFO` records for each API request except +`/healthcheck` (with or without a trailing slash): -```bash -# Production environment with database debugging -export HYPERFLEET_LOGGING_LEVEL=info # Application logs remain at INFO -export HYPERFLEET_LOGGING_FORMAT=json # Production format -export HYPERFLEET_DATABASE_DEBUG=true # Force all SQL queries to be logged -./bin/hyperfleet-api serve -``` +- `HTTP request received` with `method`, `path`, `remote_addr`, `user_agent`, + and masked request `headers` +- `HTTP request completed` with `method`, `path`, `status_code`, `duration_ms`, + `remote_addr`, and `user_agent` -**Priority:** -1. If `HYPERFLEET_DATABASE_DEBUG=true`, all SQL queries are logged (GORM Info level) -2. Otherwise, follow `HYPERFLEET_LOGGING_LEVEL` mapping (see table above) +Because request ID and OpenTelemetry middleware run first, these records also +carry `request_id` and, when tracing is enabled, `trace_id` and `span_id`. -### Database Log Examples +The middleware deliberately does not log request or response bodies. If code +has a justified need to log a body, it must call `MaskingMiddleware.MaskBody` +before logging it and should still prefer a small allowlist of safe fields. -**Fast query (LOG_LEVEL=debug or DB_DEBUG=true):** +## Data masking -JSON format: -```json -{ - "timestamp": "2026-01-14T11:31:29.788683+08:00", - "level": "info", - "message": "GORM query", - "duration_ms": 9.052167, - "rows": 1, - "sql": "INSERT INTO \"clusters\" (\"id\",\"created_time\",...) VALUES (...)", - "component": "api", - "version": "0120ac6-modified", - "hostname": "yasun-mac", - "request_id": "38EOuujxBDUduP0hYLxVGMm69Dq", - "transaction_id": 1157 -} -``` +Masking is enabled by default. The default sensitive headers are: -Text format: -```text -2026-01-14T11:34:23+08:00 INFO [api] [0120ac6-modified] [yasun-mac] GORM query request_id=38EPGnassU9SLNZ82XiXZLiWS4i duration_ms=10.135875 rows=1 sql="INSERT INTO \"clusters\" (\"id\",\"created_time\",...) VALUES (...)" -``` +- `Authorization` +- `X-API-Key` +- `Cookie` +- `X-Auth-Token` +- `X-Forwarded-Authorization` -**Slow query (>200ms, visible at all log levels except error):** +Header matching is case-insensitive. Sensitive header values are replaced by +`***REDACTED***` in the request-start record. -```json -{ - "timestamp": "2026-01-14T12:00:00Z", - "level": "warn", - "message": "GORM query", - "duration_ms": 250.5, - "rows": 1000, - "sql": "SELECT * FROM clusters WHERE ...", - "request_id": "...", - "transaction_id": 1234 -} -``` +Body-field matching is case-insensitive and recursively traverses JSON objects +and arrays. For invalid or oversized JSON, `MaskBody` applies best-effort text +fallback masking. -**Database error (visible at all log levels):** +To replace the header list through an environment variable, use a +comma-separated value: -```json -{ - "timestamp": "2026-01-14T12:00:00Z", - "level": "error", - "message": "GORM query error", - "error": "pq: duplicate key value violates unique constraint \"idx_clusters_name\"", - "duration_ms": 10.5, - "rows": 0, - "sql": "INSERT INTO \"clusters\" ...", - "request_id": "..." -} +```bash +export HYPERFLEET_LOGGING_MASKING_HEADERS='Authorization,Cookie,X-Custom-Auth' ``` -### Configuration Priority +Disabling masking makes logged request headers visible. Do so only in a +controlled environment with non-sensitive traffic. -The `HYPERFLEET_DATABASE_DEBUG` environment variable takes precedence over the global logging level. When `HYPERFLEET_DATABASE_DEBUG` is not set, database logging automatically follows `HYPERFLEET_LOGGING_LEVEL`. +## Database logging -## Log Output Examples +The GORM adapter emits structured records using the request context, so query +records can include request, trace, and resource correlation: -### Error Logs with Stack Traces +| Event | Level | Fields | +| --- | --- | --- | +| Normal query | `INFO` | `duration_ms`, `rows`, `sql` | +| Query slower than 200 ms | `WARN` | `duration_ms`, `threshold_ms`, `rows`, `sql` | +| Query failure other than record-not-found | `ERROR` | `error`, `duration_ms`, `rows`, `sql` | -**Code**: -```go -logger.With(ctx, "host", "postgres.svc").WithError(err).Error("Failed to connect to database") -``` +For the serving API, GORM verbosity is selected as follows: -**JSON Output**: -```json -{ - "timestamp": "2026-01-09T12:30:45Z", - "level": "error", - "source": {"function": "db.Connect", "file": "/app/db/connection.go", "line": 45}, - "message": "Failed to connect to database", - "host": "postgres.svc", - "error": "dial tcp: lookup postgres.svc: no such host", - "component": "hyperfleet-api", - "version": "v1.2.3", - "hostname": "pod-abc", - "request_id": "2C9zKDz8xQMqF3yH", - "stack_trace": [ - "/workspace/pkg/db/connection.go:45 github.com/openshift-hyperfleet/hyperfleet-api/pkg/db.Connect", - "/workspace/pkg/db/factory.go:78 github.com/openshift-hyperfleet/hyperfleet-api/pkg/db.NewSessionFactory", - "/workspace/cmd/hyperfleet-api/servecmd/cmd.go:123 main.setupDatabase" - ] -} -``` +| Configuration | GORM mode | Records offered to `slog` | +| --- | --- | --- | +| `database.debug=true` | Info | All queries, slow queries, and errors | +| Otherwise, `logging.level=debug` | Info | All queries, slow queries, and errors | +| Otherwise, `logging.level=info` or `warn` | Warn | Slow queries and errors | +| Otherwise, `logging.level=error` | Silent | No GORM records | -**Text Output** (multi-line stack trace for readability): -```text -2026-01-09T12:30:45Z ERROR [hyperfleet-api] [v1.2.3] [pod-abc] Failed to connect to database request_id=2C9zKDz8xQMqF3yH host=postgres.svc error="dial tcp: lookup postgres.svc: no such host" - stack_trace: - /workspace/pkg/db/connection.go:45 github.com/openshift-hyperfleet/hyperfleet-api/pkg/db.Connect - /workspace/pkg/db/factory.go:78 github.com/openshift-hyperfleet/hyperfleet-api/pkg/db.NewSessionFactory - /workspace/cmd/hyperfleet-api/servecmd/cmd.go:123 main.setupDatabase -``` +The global `slog` level still filters GORM records. For example, +`database.debug=true` with `logging.level=warn` does not make normal +`INFO`-level query records visible. Use `logging.level=debug` or `info` while +temporarily enabling database debug if all SQL is required. -**Note**: Error-level logs automatically include stack traces. +```bash +HYPERFLEET_LOGGING_LEVEL=info \ +HYPERFLEET_DATABASE_DEBUG=true \ +./bin/hyperfleet-api serve +``` -## OpenTelemetry Integration +SQL records may include query arguments. Enable full query logging only for +short-lived diagnosis and avoid storing production query logs where sensitive +data could be exposed. -### Initialization +## OpenTelemetry integration -OpenTelemetry is initialized in `cmd/hyperfleet-api/servecmd/cmd.go` (see `runServe()` function, lines ~74-110). +Tracing has its own application configuration, separate from logging: -**Key behavior:** -- Checks `HYPERFLEET_TRACING_ENABLED` environment variable first (tracing standard) -- Falls back to config file setting if not set -- Uses `OTEL_SERVICE_NAME` if set, otherwise defaults to `"hyperfleet-api"` -- Initializes trace provider via `telemetry.InitTraceProvider(ctx, serviceName, api.Version)` -- Shuts down with timeout during graceful shutdown +```yaml +tracing: + enabled: true + service_name: hyperfleet-api +``` -See the actual implementation for complete error handling and shutdown logic. +The application default is enabled. The Helm chart may supply a different value +through `HYPERFLEET_TRACING_ENABLED`. The former +`logging.otel.enabled` configuration key is accepted for compatibility but is +deprecated; `tracing.enabled` wins when both are set. -### Trace Propagation +### Environment variables -The OTel middleware automatically: -1. Extracts W3C trace context from incoming HTTP headers -2. Creates or continues spans for each request -3. Injects trace_id and span_id into the logger context -4. Exports traces to stdout (can be configured for other exporters) +| Variable | Purpose | Application default | +| --- | --- | --- | +| `HYPERFLEET_TRACING_ENABLED` | Enables provider setup and HTTP tracing middleware | `true` | +| `OTEL_SERVICE_NAME` | Service name attached to spans | `hyperfleet-api` | +| `OTEL_EXPORTER_OTLP_ENDPOINT` | OTLP collector endpoint; absence selects the stdout trace exporter | unset | +| `OTEL_EXPORTER_OTLP_PROTOCOL` | `grpc` or `http/protobuf` | `grpc` | +| `OTEL_TRACES_SAMPLER` | Sampling strategy | `parentbased_traceidratio` | +| `OTEL_TRACES_SAMPLER_ARG` | Ratio from `0.0` to `1.0` for ratio samplers | `1.0` | +| `OTEL_PROPAGATORS` | Comma-separated propagation formats | `tracecontext,baggage` | +| `OTEL_RESOURCE_ATTRIBUTES` | Extra resource attributes as `key=value` pairs | unset | -### Sampling +Supported sampler values are `always_on`, `always_off`, `traceidratio`, +`parentbased_always_on`, `parentbased_always_off`, and +`parentbased_traceidratio`. An unknown sampler or invalid ratio falls back to +the default sampler/rate and emits a warning. -By default, all traces are sampled (`parentbased_always_on`). To reduce overhead, switch to ratio-based sampling: +For a production collector with 10% root-span sampling: ```bash +export HYPERFLEET_TRACING_ENABLED=true +# Use HTTPS for TLS in production; HTTP is suitable for local development only. +export OTEL_EXPORTER_OTLP_ENDPOINT=https://otel-collector.example.com:4317 +export OTEL_EXPORTER_OTLP_PROTOCOL=grpc export OTEL_TRACES_SAMPLER=parentbased_traceidratio -export OTEL_TRACES_SAMPLER_ARG=0.1 # 10% of root spans +export OTEL_TRACES_SAMPLER_ARG=0.1 ``` -**Sampler types:** -- `parentbased_always_on`: Sample all root spans (default) -- `parentbased_traceidratio`: Sample a percentage of root spans (set rate via `OTEL_TRACES_SAMPLER_ARG`) -- `always_on` / `always_off`: Sample all or none, ignoring parent context +The HTTP middleware extracts standard W3C trace context, creates or continues a +span, and places its IDs in logging context. Route templates are used for span +names when available to avoid high-cardinality names. The trace provider is +flushed during graceful shutdown. -## Data Masking +If no OTLP endpoint is configured while tracing is enabled, spans are written +by the stdout trace exporter. Set an endpoint or disable tracing when that +additional stdout output is not wanted. -Sensitive data is automatically masked when `MASKING_ENABLED=true`: +## Testing logging behavior -**Default masked headers**: `Authorization`, `Cookie`, `X-API-Key`, `X-Auth-Token` -**Default masked fields**: `password`, `token`, `secret`, `api_key`, `client_secret` - -To add custom masking rules to a loaded `*config.ApplicationConfig` named `cfg`: +Construct an isolated logger backed by a buffer and assert decoded fields. Do +not compare complete records containing timestamps or generated request IDs. ```go -cfg.Logging.Masking.Headers = append( - cfg.Logging.Masking.Headers, - "X-Custom-Auth-Header", -) - -cfg.Logging.Masking.Fields = append( - cfg.Logging.Masking.Fields, - "credit_card", - "ssn", -) +func TestResourceLog(t *testing.T) { + var output bytes.Buffer + log := logger.NewLogger("test-version", logger.HandlerConfig{ + Level: slog.LevelInfo, + Format: hfl.FormatJSON, + Output: &output, + Hostname: "test-host", + }) + + ctx := hfl.WithResourceType(context.Background(), "Cluster") + ctx = hfl.WithResourceID(ctx, "cluster-123") + ctx, err := logger.WithRequestID(ctx) + if err != nil { + t.Fatal(err) + } + log.InfoContext(ctx, "Resource updated") + + var record map[string]any + if err := json.Unmarshal(output.Bytes(), &record); err != nil { + t.Fatal(err) + } + if got := record["component"]; got != "api" { + t.Fatalf("component = %v, want api", got) + } + if got := record["resource_id"]; got != "cluster-123" { + t.Fatalf("resource_id = %v, want cluster-123", got) + } + if _, ok := record["request_id"].(string); !ok { + t.Fatalf("request_id = %T, want string", record["request_id"]) + } +} ``` -## Best Practices - -### Application Logging - -1. **Always use context**: `logger.Info(ctx, "msg")` not `slog.Info("msg")` -2. **Use WithError for errors**: `logger.WithError(ctx, err).Error(...)` not `"error", err` -3. **Use field constants**: `logger.FieldEnvironment` not `"environment"` -4. **Use HTTP helpers**: `logger.HTTPMethod(r.Method)` not `"method", r.Method` -5. **Chain for readability**: `logger.With(ctx, ...).WithError(err).Error(...)` -6. **Never log sensitive data**: Always sanitize passwords, tokens, connection strings -7. **Choose appropriate levels**: DEBUG (dev), INFO (normal), WARN (client error), ERROR (server error) - -### Database Logging - -1. **Use HYPERFLEET_LOGGING_LEVEL for database logs**: Don't set `HYPERFLEET_DATABASE_DEBUG` unless specifically debugging database issues -2. **Production default**: `HYPERFLEET_LOGGING_LEVEL=info` hides fast queries, shows slow queries (>200ms) -3. **Temporary debugging**: Use `HYPERFLEET_DATABASE_DEBUG=true` for production database troubleshooting, then disable it -4. **Development**: Use `HYPERFLEET_LOGGING_LEVEL=debug` to see all SQL queries during development -5. **High-traffic systems**: Consider `HYPERFLEET_LOGGING_LEVEL=warn` to minimize database log volume -6. **Monitor slow queries**: Review WARN-level GORM logs for queries exceeding 200ms threshold - -## Troubleshooting - -### Logs Not Appearing - -1. Check log level: `export HYPERFLEET_LOGGING_LEVEL=debug` -2. Verify text mode: `export HYPERFLEET_LOGGING_FORMAT=text` (for human-readable output) -3. Check context propagation: Ensure middleware chain is correct - -### Missing request_id - -Verify `RequestIDMiddleware` is registered before `RequestLoggingMiddleware`: +Tests that must replace the process-wide logger should restore it: ```go -mainRouter.Use(logger.RequestIDMiddleware) -mainRouter.Use(middleware.OTelMiddleware) -mainRouter.Use(logging.RequestLoggingMiddleware) +previous := slog.Default() +slog.SetDefault(testLogger) +t.Cleanup(func() { slog.SetDefault(previous) }) ``` -### Missing trace_id/span_id +Useful commands are: -1. Check tracing is enabled: `export HYPERFLEET_TRACING_ENABLED=true` -2. Verify middleware order: `OTelMiddleware` must be after `RequestIDMiddleware` -3. Check sampling rate: `export OTEL_TRACES_SAMPLER_ARG=1.0` (for testing - trace all requests) - -### Data Not Masked - -1. Check masking is enabled: `export HYPERFLEET_LOGGING_MASKING_ENABLED=true` -2. Verify field names match configuration (case-insensitive) -3. Check JSON structure: Masking only works on top-level fields +```bash +HYPERFLEET_LOGGING_LEVEL=debug make test +HYPERFLEET_TRACING_ENABLED=false make test-integration +``` -### SQL Queries Not Appearing +## Troubleshooting -1. Check log level: `export HYPERFLEET_LOGGING_LEVEL=debug` (to see all SQL queries) -2. Check database debug: `export HYPERFLEET_DATABASE_DEBUG=true` (to force SQL logging at any log level) -3. Verify queries are executing: Check if API operations complete successfully -4. Check log format: Use `HYPERFLEET_LOGGING_FORMAT=text` for easier debugging +### Logs do not appear -### Too Many SQL Queries in Logs +- Confirm that the record level is at or above `HYPERFLEET_LOGGING_LEVEL`. +- Confirm whether `HYPERFLEET_LOGGING_OUTPUT` sends records to `stdout` or + `stderr`. +- Use text/debug mode locally to make filtering easier. -1. Production mode: `export HYPERFLEET_LOGGING_LEVEL=info` (hides fast queries < 200ms) -2. Disable database debug: `export HYPERFLEET_DATABASE_DEBUG=false` or unset it -3. Minimal mode: `export HYPERFLEET_LOGGING_LEVEL=warn` (only slow queries and errors) -4. Silent mode: `export HYPERFLEET_LOGGING_LEVEL=error` (no SQL queries logged) +### `request_id` is missing -### Only Want to See Slow Queries +- Use a `slog.*Context` method with the request-derived context. +- Confirm `RequestIDMiddleware` wraps the handler that emits the record. +- Do not replace the request context with `context.Background()` downstream. -Use production default configuration: -```bash -export HYPERFLEET_LOGGING_LEVEL=info -export HYPERFLEET_LOGGING_FORMAT=json -export HYPERFLEET_DATABASE_DEBUG=false # or leave unset -``` +### `trace_id` or `span_id` is missing -This will only log SQL queries that take longer than 200ms. +- Confirm `HYPERFLEET_TRACING_ENABLED=true`. +- Confirm the log uses the context passed through `OTelMiddleware`. +- For local diagnosis, use `OTEL_TRACES_SAMPLER_ARG=1.0`. -## Testing +### A sensitive header is visible -### Unit Tests +- Confirm `HYPERFLEET_LOGGING_MASKING_ENABLED=true`. +- Confirm the header appears in `HYPERFLEET_LOGGING_MASKING_HEADERS`; replacing + this variable replaces the configured list. +- Remember that application log call sites outside request logging must choose + and sanitize their own attributes. -```go -func TestLogging(t *testing.T) { - // Create context with request ID - ctx, err := logger.WithRequestID(context.Background()) - if err != nil { - t.Fatalf("Failed to create request ID: %v", err) - } - - // Log with context - logger.With(ctx, "key", "value").Info("Test message") - - // Verify request_id is included - // (Use a test handler to capture logs) -} -``` +### SQL queries do not appear -### Integration Tests +- Set `HYPERFLEET_LOGGING_LEVEL=debug` to enable and display normal queries. +- Alternatively, set `HYPERFLEET_DATABASE_DEBUG=true` with an overall level of + `debug` or `info`. +- At `info` or `warn` without database debug, only queries slower than 200 ms + and query errors are offered by GORM. +- At `error` without database debug, GORM logging is silent. -```bash -# Run tests with debug logging -HYPERFLEET_LOGGING_LEVEL=debug go test ./test/integration/... +### Too many SQL queries appear -# Run tests without OTel -HYPERFLEET_TRACING_ENABLED=false go test ./... -``` +- Disable `HYPERFLEET_DATABASE_DEBUG`. +- Use `HYPERFLEET_LOGGING_LEVEL=info` for slow queries and errors without normal + query records. +- Use `warn` to suppress other informational application records as well. ## References -- [slog Documentation](https://pkg.go.dev/log/slog) -- [OpenTelemetry Go SDK](https://opentelemetry.io/docs/languages/go/) +- [Application configuration](config.md) +- [Go `log/slog` package](https://pkg.go.dev/log/slog) +- [OpenTelemetry Go documentation](https://opentelemetry.io/docs/languages/go/) - [W3C Trace Context](https://www.w3.org/TR/trace-context/) -- [HyperFleet Architecture](https://github.com/openshift-hyperfleet/architecture) +- [HyperFleet logging specification](https://github.com/openshift-hyperfleet/architecture/blob/main/hyperfleet/standards/logging-specification.md) +- [HyperFleet tracing standard](https://github.com/openshift-hyperfleet/architecture/blob/main/hyperfleet/standards/tracing.md) diff --git a/go.mod b/go.mod index a1833520..6e5363c1 100755 --- a/go.mod +++ b/go.mod @@ -19,6 +19,7 @@ require ( github.com/oapi-codegen/runtime v1.7.0 github.com/onsi/gomega v1.43.0 github.com/openshift-hyperfleet/hyperfleet-api-spec v1.0.27 + github.com/openshift-hyperfleet/hyperfleet-logger v0.0.0-20260811173525-c9f9e282d029 github.com/prometheus/client_golang v1.24.1 github.com/prometheus/client_model v0.6.2 github.com/spf13/cobra v1.10.2 diff --git a/go.sum b/go.sum index b53fc196..407d8615 100644 --- a/go.sum +++ b/go.sum @@ -190,6 +190,8 @@ github.com/opencontainers/image-spec v1.1.1 h1:y0fUlFfIZhPF1W537XOLg0/fcx6zcHCJw github.com/opencontainers/image-spec v1.1.1/go.mod h1:qpqAh3Dmcf36wStyyWU+kCeDgrGnAve2nCC8+7h8Q0M= github.com/openshift-hyperfleet/hyperfleet-api-spec v1.0.27 h1:wtLN7KFgsDHaYDBElMcOUjHVeqjRs6dlGOWiobS1/qk= github.com/openshift-hyperfleet/hyperfleet-api-spec v1.0.27/go.mod h1:KITzIAd8HcMpH5lXdHFjgk45dvL6XLpP3wwz8iK+KCI= +github.com/openshift-hyperfleet/hyperfleet-logger v0.0.0-20260811173525-c9f9e282d029 h1:c3GdD3EUdR9lRjNot+aBIxVbAXbOSTtiQpWVTHnFHaU= +github.com/openshift-hyperfleet/hyperfleet-logger v0.0.0-20260811173525-c9f9e282d029/go.mod h1:5Nh2IMS2MouehZ4UiRXFMjhuwdys2DX26J4vArmXe6Y= github.com/pelletier/go-toml/v2 v2.4.3 h1:GTRvJQutkOSftxIFD5xw9aepkYNuPWmVJpffdDPYVpY= github.com/pelletier/go-toml/v2 v2.4.3/go.mod h1:2gIqNv+qfxSVS7cM2xJQKtLSTLUE9V8t9Stt+h56mCY= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= diff --git a/pkg/api/error.go b/pkg/api/error.go index bffb6ba8..4bfdccb9 100755 --- a/pkg/api/error.go +++ b/pkg/api/error.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "net/http" "os" "time" @@ -34,7 +35,7 @@ func SendNotFound(w http.ResponseWriter, r *http.Request) { data, err := json.Marshal(body) if err != nil { - logger.WithError(r.Context(), err).Error("Failed to marshal not found response") + slog.ErrorContext(r.Context(), "Failed to marshal not found response", "error", err) SendPanic(w, r) return } @@ -43,7 +44,7 @@ func SendNotFound(w http.ResponseWriter, r *http.Request) { _, err = w.Write(data) if err != nil { err = fmt.Errorf("can't send response body for request '%s'", r.URL.Path) - logger.WithError(r.Context(), err).Error("Failed to send response") + slog.ErrorContext(r.Context(), "Failed to send response", "error", err) } } @@ -84,7 +85,7 @@ func SendPanic(w http.ResponseWriter, r *http.Request) { r.URL.Path, err.Error(), ) - logger.WithError(r.Context(), err).Error("Failed to send panic response") + slog.ErrorContext(r.Context(), "Failed to send panic response", "error", err) } } @@ -111,7 +112,7 @@ func init() { panicBody, err = json.Marshal(panicError) if err != nil { err = fmt.Errorf("can't create the panic error body: %s", err.Error()) - logger.WithError(ctx, err).Error("Failed to create panic error body") + slog.ErrorContext(ctx, "Failed to create panic error body", "error", err) os.Exit(1) } } diff --git a/pkg/api/response/problem_details.go b/pkg/api/response/problem_details.go index a812950a..6785abda 100644 --- a/pkg/api/response/problem_details.go +++ b/pkg/api/response/problem_details.go @@ -3,6 +3,7 @@ package response import ( "context" "encoding/json" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" @@ -29,9 +30,8 @@ func WriteProblemDetailsResponse(w http.ResponseWriter, r *http.Request, code in } func logResponseError(ctx context.Context, r *http.Request, code int, message string, err error) { - logger.With(ctx, - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(ctx, + message, logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(code), - ).WithError(err).Error(message) + logger.HTTPStatusCode(code), "error", err) } diff --git a/pkg/auth/helpers.go b/pkg/auth/helpers.go index 580b03ab..bd414d8f 100755 --- a/pkg/auth/helpers.go +++ b/pkg/auth/helpers.go @@ -2,6 +2,7 @@ package auth import ( "context" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api/response" @@ -20,9 +21,9 @@ func handleError(ctx context.Context, w http.ResponseWriter, r *http.Request, co instance = r.URL.Path } if err.HTTPCode >= 400 && err.HTTPCode <= 499 { - logger.WithError(ctx, err).Warn("Client error occurred") + slog.WarnContext(ctx, "Client error occurred", "error", err) } else { - logger.WithError(ctx, err).Error("Server error occurred") + slog.ErrorContext(ctx, "Server error occurred", "error", err) } response.WriteProblemDetailsResponse(w, r, err.HTTPCode, err.AsProblemDetails(instance, traceID)) diff --git a/pkg/auth/helpers_test.go b/pkg/auth/helpers_test.go new file mode 100644 index 00000000..c7239708 --- /dev/null +++ b/pkg/auth/helpers_test.go @@ -0,0 +1,49 @@ +package auth + +import ( + "bytes" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "testing" + + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" + + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" +) + +func TestHandleError_OnlyServerFailuresIncludeStack(t *testing.T) { + for _, tt := range []struct { + name string + code string + status int + stack bool + }{ + {name: "missing credentials", code: errors.CodeAuthNoCredentials, status: http.StatusUnauthorized}, + {name: "internal failure", code: errors.CodeInternalGeneral, status: http.StatusInternalServerError, stack: true}, + } { + t.Run(tt.name, func(t *testing.T) { + var output bytes.Buffer + previous := slog.Default() + slog.SetDefault(logger.NewLogger("test", logger.HandlerConfig{ + Level: slog.LevelInfo, Format: hfl.FormatJSON, Output: &output, + })) + t.Cleanup(func() { slog.SetDefault(previous) }) + req := httptest.NewRequest(http.MethodGet, "/test", nil).WithContext(t.Context()) + res := httptest.NewRecorder() + handleError(req.Context(), res, req, tt.code, "test error") + if res.Code != tt.status { + t.Errorf("HTTP status = %d, want %d", res.Code, tt.status) + } + var record map[string]any + if err := json.Unmarshal(output.Bytes(), &record); err != nil { + t.Fatal(err) + } + if _, ok := record["stack_trace"]; ok != tt.stack { + t.Errorf("stack present = %v, want %v", ok, tt.stack) + } + }) + } +} diff --git a/pkg/auth/jwt_handler.go b/pkg/auth/jwt_handler.go index 39a21927..d887098f 100644 --- a/pkg/auth/jwt_handler.go +++ b/pkg/auth/jwt_handler.go @@ -7,6 +7,7 @@ import ( "encoding/json" "errors" "fmt" + "log/slog" "net/http" "os" "strings" @@ -18,7 +19,6 @@ import ( "github.com/openshift-hyperfleet/hyperfleet-api/pkg/config" hferrors "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) const ( @@ -149,7 +149,7 @@ func (h *JWTHandler) Middleware(next http.Handler) http.Handler { // No validator matched - return the most appropriate error if lastErr != nil { - logger.WithError(r.Context(), lastErr).Warn("JWT validation failed") + slog.WarnContext(r.Context(), "JWT validation failed", "error", lastErr) if errors.Is(lastErr, jwt.ErrTokenExpired) { handleError(r.Context(), w, r, hferrors.CodeAuthExpiredToken, "JWT token has expired") } else { @@ -270,14 +270,15 @@ func newStorageWithCA(ctx context.Context, jwkURL, caFile string) (jwkset.Storag if err != nil { return nil, err } - logger.With(ctx, "url", jwkURL, "ca_file", caFile).Info("JWKS client configured with custom CA") + slog.InfoContext(ctx, "JWKS client configured with custom CA", "url", jwkURL, "ca_file", caFile) storage, err := jwkset.NewStorageFromHTTP(jwkURL, jwkset.HTTPClientStorageOptions{ Client: httpClient, Ctx: ctx, NoErrorReturnFirstHTTPReq: true, RefreshErrorHandler: func(ctx context.Context, err error) { - logger.With(ctx, "url", jwkURL, "ca_file", caFile).WithError(err). - Error("failed to refresh JWKS from URL with custom CA") + slog.ErrorContext(ctx, + "failed to refresh JWKS from URL with custom CA", "url", jwkURL, "ca_file", caFile, "error", err, + ) }, RefreshInterval: defaultJWKSRefreshInterval, }) diff --git a/pkg/closer/closer.go b/pkg/closer/closer.go index c0d3ba47..1c7f2fc1 100644 --- a/pkg/closer/closer.go +++ b/pkg/closer/closer.go @@ -4,10 +4,9 @@ import ( "context" "errors" "fmt" + "log/slog" "sync" "time" - - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) type Closer struct { @@ -47,10 +46,10 @@ func (c *Closer) Close() error { err := fns[i]() elapsed := time.Since(start) if err != nil { - logger.With(ctx, "step", i, "duration", elapsed).WithError(err).Error("closer: step failed") + slog.ErrorContext(ctx, "closer: step failed", "step", i, "duration", elapsed, "error", err) joined = errors.Join(joined, fmt.Errorf("step %d: %w", i, err)) } else { - logger.With(ctx, "step", i, "duration", elapsed).Info("closer: step completed") + slog.InfoContext(ctx, "closer: step completed", "step", i, "duration", elapsed) } } diff --git a/pkg/config/flags.go b/pkg/config/flags.go index 0cdc1c34..484f9d93 100644 --- a/pkg/config/flags.go +++ b/pkg/config/flags.go @@ -52,7 +52,7 @@ func AddDatabaseFlags(cmd *cobra.Command) { } // AddLoggingFlags adds logging configuration flags following standard naming -// Format: --log- maps to HYPERFLEET_LOGGING_ and logging. +// Format: --log- maps to HYPERFLEET_LOGGING_ and logging.. func AddLoggingFlags(cmd *cobra.Command) { defaults := NewLoggingConfig() diff --git a/pkg/config/loader.go b/pkg/config/loader.go index a8430391..5b188c2c 100644 --- a/pkg/config/loader.go +++ b/pkg/config/loader.go @@ -3,6 +3,7 @@ package config import ( "context" "fmt" + "log/slog" "os" "reflect" "strings" @@ -11,8 +12,6 @@ import ( "github.com/spf13/cobra" "github.com/spf13/pflag" "github.com/spf13/viper" - - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // ConfigLoader handles loading and validating application configuration @@ -72,7 +71,6 @@ func (l *ConfigLoader) Load(ctx context.Context, cmd *cobra.Command) (*Applicati "configuration unmarshal failed: %w\nThis usually means unknown/misspelled fields in config file", err) } - // Step 6.5: Migrate deprecated configuration before validation l.migrateDeprecatedConfig(ctx, config) @@ -104,7 +102,7 @@ func (l *ConfigLoader) resolveAndReadConfigFile(ctx context.Context, cmd *cobra. return err } explicitPath = true - logger.With(ctx, "config_path", configPath, "source", "flag").Info("Config file specified via --config flag") + slog.InfoContext(ctx, "Config file specified via --config flag", "config_path", configPath, "source", "flag") } // Priority 2: HYPERFLEET_CONFIG environment variable @@ -112,7 +110,7 @@ func (l *ConfigLoader) resolveAndReadConfigFile(ctx context.Context, cmd *cobra. if envPath := os.Getenv("HYPERFLEET_CONFIG"); envPath != "" { configPath = envPath explicitPath = true - logger.With(ctx, "config_path", configPath, "source", "env").Info("Config file specified via HYPERFLEET_CONFIG") + slog.InfoContext(ctx, "Config file specified via HYPERFLEET_CONFIG", "config_path", configPath, "source", "env") } } @@ -122,22 +120,24 @@ func (l *ConfigLoader) resolveAndReadConfigFile(ctx context.Context, cmd *cobra. prodPath := "/etc/hyperfleet/config.yaml" if _, err := os.Stat(prodPath); err == nil { configPath = prodPath - logger.With(ctx, "config_path", configPath, "source", "default_production"). - Info("Using production default config file") + slog.InfoContext(ctx, + "Using production default config file", "config_path", configPath, "source", "default_production", + ) } else { // Try development path devPath := "./configs/config.yaml" if _, err := os.Stat(devPath); err == nil { configPath = devPath - logger.With(ctx, "config_path", configPath, "source", "default_development"). - Info("Using development default config file") + slog.InfoContext(ctx, + "Using development default config file", "config_path", configPath, "source", "default_development", + ) } } } // If no config file found, continue with env vars and flags only if configPath == "" { - logger.Info(ctx, "No config file found, using environment variables and flags only") + slog.InfoContext(ctx, "No config file found, using environment variables and flags only") return nil } @@ -156,11 +156,11 @@ func (l *ConfigLoader) resolveAndReadConfigFile(ctx context.Context, cmd *cobra. return fmt.Errorf("failed to read config file %s: %w", configPath, err) } // Just log warning if using default path - logger.With(ctx, "config_path", configPath).WithError(err).Warn("Failed to read default config file, continuing") + slog.WarnContext(ctx, "Failed to read default config file, continuing", "config_path", configPath, "error", err) return nil } - logger.With(ctx, "config_path", configPath).Info("Successfully loaded config file") + slog.InfoContext(ctx, "Successfully loaded config file", "config_path", configPath) return nil } @@ -254,8 +254,10 @@ func (l *ConfigLoader) migrateDeprecatedConfig(ctx context.Context, config *Appl if tls.Enabled && tls.CertFile == "" && tls.KeyFile == "" { tls.CertFile = config.Server.TLS.CertFile tls.KeyFile = config.Server.TLS.KeyFile - logger.With(ctx, "server", name). - Warn("TLS enabled without cert/key - inheriting from server.tls (deprecated: set cert_file/key_file explicitly)") + slog.WarnContext(ctx, + "TLS enabled without cert/key - inheriting from server.tls (deprecated: set cert_file/key_file explicitly)", + "server", name, + ) } } propagateTLS("health", &config.Health.TLS) @@ -263,10 +265,10 @@ func (l *ConfigLoader) migrateDeprecatedConfig(ctx context.Context, config *Appl if l.viper.IsSet("logging.otel.enabled") { if l.viper.IsSet("tracing.enabled") { - logger.Warn(ctx, "logging.otel.enabled is deprecated and ignored because tracing.enabled is also set") + slog.WarnContext(ctx, "logging.otel.enabled is deprecated and ignored because tracing.enabled is also set") } else { config.Tracing.Enabled = config.Logging.OTel.Enabled - logger.Warn(ctx, "logging.otel.enabled is deprecated, use tracing.enabled instead") + slog.WarnContext(ctx, "logging.otel.enabled is deprecated, use tracing.enabled instead") } } } @@ -432,6 +434,7 @@ func (l *ConfigLoader) bindFlags(cmd *cobra.Command) { l.bindPFlag("logging.output", cmd.Flags().Lookup("log-output")) l.bindPFlag("logging.masking.enabled", cmd.Flags().Lookup("log-masking-enabled")) l.bindPFlag("logging.masking.headers", cmd.Flags().Lookup("log-masking-sensitive-headers")) + // Deprecated compatibility flag; the value is accepted but has no runtime effect. l.bindPFlag("logging.masking.fields", cmd.Flags().Lookup("log-masking-sensitive-fields")) // Metrics flags: --metrics-* -> metrics.* diff --git a/pkg/config/logging_test.go b/pkg/config/logging_test.go index 9eb1d521..2c7fec8d 100644 --- a/pkg/config/logging_test.go +++ b/pkg/config/logging_test.go @@ -21,7 +21,7 @@ func TestNewLoggingConfig_Defaults(t *testing.T) { Expect(cfg.Output).To(Equal("stdout")) Expect(cfg.Masking.Enabled).To(BeTrue()) Expect(cfg.Masking.Headers).NotTo(BeEmpty()) - Expect(cfg.Masking.Fields).NotTo(BeEmpty()) + Expect(cfg.Masking.Fields).NotTo(BeEmpty()) // Deprecated compatibility default. } // TestConfigLoader_LoggingFromEnv tests loading logging config from environment @@ -140,39 +140,6 @@ func TestLoggingConfig_GetSensitiveHeadersList(t *testing.T) { } } -// TestLoggingConfig_GetSensitiveFieldsList tests the fields array accessor -func TestLoggingConfig_GetSensitiveFieldsList(t *testing.T) { - RegisterTestingT(t) - - tests := []struct { - name string - input []string - expected []string - }{ - { - name: "standard list", - input: []string{"password", "secret", "token"}, - expected: []string{"password", "secret", "token"}, - }, - { - name: "empty array", - input: []string{}, - expected: []string{}, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - cfg := NewLoggingConfig() - cfg.Masking.Fields = tt.input - - fields := cfg.GetSensitiveFieldsList() - - Expect(fields).To(Equal(tt.expected)) - }) - } -} - // ============================================================== // Comprehensive Config Loader Tests // ============================================================== diff --git a/pkg/db/advisory_locks.go b/pkg/db/advisory_locks.go index 1a9c339c..3fda69f7 100644 --- a/pkg/db/advisory_locks.go +++ b/pkg/db/advisory_locks.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "hash/fnv" + "log/slog" "time" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" @@ -114,7 +115,7 @@ func (l *AdvisoryLock) unlock(ctx context.Context) error { l.g2 = nil if err == nil { - logger.With(ctx, logger.FieldLockDurationMs, duration.Milliseconds()).Info("Released advisory lock") + slog.InfoContext(ctx, "Released advisory lock", logger.FieldLockDurationMs, duration.Milliseconds()) } return err diff --git a/pkg/db/context.go b/pkg/db/context.go index 9fc37155..f5fd50a7 100755 --- a/pkg/db/context.go +++ b/pkg/db/context.go @@ -3,6 +3,7 @@ package db import ( "context" "errors" + "log/slog" "github.com/google/uuid" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db/internal/txcontext" @@ -69,14 +70,14 @@ func NewAdvisoryLockContext( lock, err := newAdvisoryLock(ctx, connection, &lockOwnerID, &id, &lockType) if err != nil { - logger.WithError(ctx, err).Error("Failed to create advisory lock") + slog.ErrorContext(ctx, "Failed to create advisory lock", "error", err) return ctx, lockOwnerID, err } // obtain the advisory lock (blocking) err = lock.lock() if err != nil { - logger.WithError(ctx, err).Error("Failed to acquire advisory lock") + slog.ErrorContext(ctx, "Failed to acquire advisory lock", "error", err) lock.g2.Rollback() // clean up the open transaction return ctx, lockOwnerID, err } @@ -84,7 +85,7 @@ func NewAdvisoryLockContext( locks.set(id, lockType, lock) ctx = context.WithValue(ctx, advisoryLock, locks) - logger.With(ctx, logger.FieldLockID, id, logger.FieldLockType, lockType).Info("Acquired advisory lock") + slog.InfoContext(ctx, "Acquired advisory lock", logger.FieldLockID, id, logger.FieldLockType, lockType) return ctx, lockOwnerID, nil } @@ -93,13 +94,13 @@ func NewAdvisoryLockContext( func Unlock(ctx context.Context, callerUUID string) { locks, ok := ctx.Value(advisoryLock).(advisoryLockMap) if !ok { - logger.Error(ctx, "Could not retrieve locks from context") + slog.ErrorContext(ctx, "Could not retrieve locks from context") return } for k, lock := range locks { if lock.ownerUUID == nil { - logger.With(ctx, logger.FieldLockID, lock.id).Warn("lockOwnerID could not be found in AdvisoryLock") + slog.WarnContext(ctx, "lockOwnerID could not be found in AdvisoryLock", logger.FieldLockID, lock.id) } else if *lock.ownerUUID == callerUUID { lockID := "" lockType := LockType("") @@ -112,11 +113,11 @@ func Unlock(ctx context.Context, callerUUID string) { } if err := lock.unlock(ctx); err != nil { - logger.With(ctx, logger.FieldLockID, lockID, logger.FieldLockType, lockType). - WithError(err).Error("Could not unlock lock") + slog.ErrorContext(ctx, + "Could not unlock lock", logger.FieldLockID, lockID, logger.FieldLockType, lockType, "error", err) continue } - logger.With(ctx, logger.FieldLockID, lockID, logger.FieldLockType, lockType).Info("Unlocked lock") + slog.InfoContext(ctx, "Unlocked lock", logger.FieldLockID, lockID, logger.FieldLockType, lockType) delete(locks, k) } // Note: if ownerUUID doesn't match callerUUID, the lock belongs to a different diff --git a/pkg/db/db_session/default.go b/pkg/db/db_session/default.go index 6a5462a7..e9d2c733 100755 --- a/pkg/db/db_session/default.go +++ b/pkg/db/db_session/default.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "fmt" + "log/slog" "time" "gorm.io/driver/postgres" @@ -104,11 +105,10 @@ func (f *Default) Init(config *config.DatabaseConfig) { err.Error(), )) } - logger.With(context.Background(), - "retry", attempt+1, + slog.WarnContext(context.Background(), + "Database connection failed, retrying...", "retry", attempt+1, "max_retries", config.Pool.ConnRetryAttempts, - "retry_interval", config.Pool.ConnRetryInterval, - ).WithError(err).Warn("Database connection failed, retrying...") + "retry_interval", config.Pool.ConnRetryInterval, "error", err) time.Sleep(config.Pool.ConnRetryInterval) // Close the existing handle before re-opening to avoid leaking connections @@ -132,12 +132,12 @@ func (f *Default) Init(config *config.DatabaseConfig) { // Register database metrics GORM plugin if err = db_metrics.RegisterPlugin(g2); err != nil { - logger.WithError(context.Background(), err).Warn("Failed to register database metrics plugin") + slog.WarnContext(context.Background(), "Failed to register database metrics plugin", "error", err) } // Register connection pool metrics collector if err = db_metrics.RegisterPoolCollector(dbx); err != nil { - logger.WithError(context.Background(), err).Warn("Failed to register pool metrics collector") + slog.WarnContext(context.Background(), "Failed to register pool metrics collector", "error", err) } f.config = config @@ -159,19 +159,19 @@ func (f *Default) DirectDB() *sql.DB { return f.db } -func waitForNotification(l *pq.Listener, callback func(id string)) { - ctx := context.Background() +func waitForNotification(ctx context.Context, l *pq.Listener, callback func(id string)) { for { select { case n := <-l.Notify: - logger.With(ctx, logger.FieldChannel, n.Channel).With(logger.FieldData, n.Extra).Info("Received data from channel") + slog.InfoContext(ctx, "Received data from channel", + logger.FieldChannel, n.Channel, logger.FieldData, n.Extra) callback(n.Extra) return case <-time.After(10 * time.Second): - logger.Debug(ctx, "Received no events on channel during interval. Pinging source") + slog.DebugContext(ctx, "Received no events on channel during interval. Pinging source") go func() { if err := l.Ping(); err != nil { - logger.WithError(ctx, err).Debug("Ping failed") + slog.DebugContext(ctx, "Ping failed", "error", err) } }() return @@ -182,7 +182,7 @@ func waitForNotification(l *pq.Listener, callback func(id string)) { func newListener(ctx context.Context, connstr, channel string, callback func(id string)) { plog := func(ev pq.ListenerEventType, err error) { if err != nil { - logger.WithError(ctx, err).Error("PostgreSQL listener error") + slog.ErrorContext(ctx, "PostgreSQL listener error", "error", err) } } listener := pq.NewListener(connstr, 10*time.Second, time.Minute, plog) @@ -191,9 +191,9 @@ func newListener(ctx context.Context, connstr, channel string, callback func(id panic(err) } - logger.With(ctx, logger.FieldChannel, channel).Info("Starting channeling monitor") + slog.InfoContext(ctx, "Starting channeling monitor", logger.FieldChannel, channel) for { - waitForNotification(listener, callback) + waitForNotification(ctx, listener, callback) } } diff --git a/pkg/db/db_session/test.go b/pkg/db/db_session/test.go index 056636f0..7aba0368 100755 --- a/pkg/db/db_session/test.go +++ b/pkg/db/db_session/test.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "fmt" + "log/slog" "time" "github.com/lib/pq" @@ -52,12 +53,12 @@ func (f *Test) Init(config *config.DatabaseConfig) { once.Do(func() { ctx := context.Background() if err := initDatabase(config, db.Migrate); err != nil { - logger.WithError(ctx, err).Error("Error initializing test database") + slog.ErrorContext(ctx, "Error initializing test database", "error", err) panic(fmt.Errorf("error initializing test database: %w", err)) } if err := resetDB(config); err != nil { - logger.WithError(ctx, err).Error("Error resetting test database") + slog.ErrorContext(ctx, "Error resetting test database", "error", err) panic(fmt.Errorf("error resetting test database: %w", err)) } }) diff --git a/pkg/db/migrations.go b/pkg/db/migrations.go index 9fd96c3a..0d8dce5a 100755 --- a/pkg/db/migrations.go +++ b/pkg/db/migrations.go @@ -2,12 +2,12 @@ package db import ( "context" + "log/slog" "github.com/go-gormigrate/gormigrate/v2" "gorm.io/gorm" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db/migrations" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // gormigrate is a wrapper for gorm's migration functions that adds schema versioning @@ -28,7 +28,7 @@ func MigrateWithLock(ctx context.Context, factory SessionFactory) error { // Acquire advisory lock for migrations ctx, lockOwnerID, err := NewAdvisoryLockContext(ctx, factory, MigrationsLockID, Migrations) if err != nil { - logger.WithError(ctx, err).Error("Could not lock migrations") + slog.ErrorContext(ctx, "Could not lock migrations", "error", err) return err } defer Unlock(ctx, lockOwnerID) @@ -36,11 +36,11 @@ func MigrateWithLock(ctx context.Context, factory SessionFactory) error { // Run migrations with the locked context g2 := factory.New(ctx) if err := Migrate(g2); err != nil { - logger.WithError(ctx, err).Error("Could not migrate") + slog.ErrorContext(ctx, "Could not migrate", "error", err) return err } - logger.Info(ctx, "Migration completed successfully") + slog.InfoContext(ctx, "Migration completed successfully") return nil } diff --git a/pkg/db/transactions.go b/pkg/db/transactions.go index 813f0e5f..b15507a5 100755 --- a/pkg/db/transactions.go +++ b/pkg/db/transactions.go @@ -5,13 +5,13 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "github.com/prometheus/client_golang/prometheus" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db/db_metrics" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db/internal/txcontext" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // TransactionRunner executes callbacks inside database transactions. @@ -34,7 +34,7 @@ func (r *TransactionRunner) Do(ctx context.Context, callback func(context.Contex gormTx := r.connection.New(ctx).Begin() if gormTx.Error != nil { - logger.WithError(ctx, gormTx.Error).Error("Could not begin transaction") + slog.ErrorContext(ctx, "Could not begin transaction", "error", gormTx.Error) recordTransactionError("begin", "begin_failed") return fmt.Errorf("db: begin transaction: %w", gormTx.Error) } @@ -44,7 +44,7 @@ func (r *TransactionRunner) Do(ctx context.Context, callback func(context.Contex if !completed { rollbackErr := gormTx.Rollback().Error if rollbackErr != nil && !errors.Is(rollbackErr, sql.ErrTxDone) { - logger.WithError(txCtx, rollbackErr).Error("Could not rollback transaction") + slog.ErrorContext(txCtx, "Could not rollback transaction", "error", rollbackErr) recordTransactionError("rollback", "rollback_failed") } } @@ -54,7 +54,7 @@ func (r *TransactionRunner) Do(ctx context.Context, callback func(context.Contex return fmt.Errorf("db: transaction callback: %w", err) } if err := gormTx.Commit().Error; err != nil { - logger.WithError(txCtx, err).Error("Could not commit transaction") + slog.ErrorContext(txCtx, "Could not commit transaction", "error", err) recordTransactionError("commit", "commit_failed") return fmt.Errorf("db: commit transaction: %w", err) } diff --git a/pkg/errors/errors.go b/pkg/errors/errors.go index 237a43df..57e5b048 100755 --- a/pkg/errors/errors.go +++ b/pkg/errors/errors.go @@ -3,6 +3,7 @@ package errors import ( "context" "fmt" + "log/slog" "net/http" "time" @@ -220,7 +221,7 @@ func New(code string, reason string, values ...interface{}) *ServiceError { exists, err := Find(code) if !exists { ctx := context.Background() - logger.With(ctx, logger.FieldErrorCode, code).Error("Undefined error code used") + slog.ErrorContext(ctx, "Undefined error code used", logger.FieldErrorCode, code) err = &ServiceError{ RFC9457Code: CodeInternalGeneral, Type: ErrorTypeInternal, @@ -373,7 +374,7 @@ func FailedToParseSearch(reason string, values ...interface{}) *ServiceError { func DatabaseAdvisoryLock(err error) *ServiceError { // Log the full error server-side for debugging ctx := context.Background() - logger.WithError(ctx, err).Error("Database advisory lock error") + slog.ErrorContext(ctx, "Database advisory lock error", "error", err) // Return a generic message to avoid leaking sensitive database info return New(CodeInternalDatabase, "internal database error") } diff --git a/pkg/handlers/helpers.go b/pkg/handlers/helpers.go index 72db7c3a..2b3ad25a 100755 --- a/pkg/handlers/helpers.go +++ b/pkg/handlers/helpers.go @@ -4,6 +4,7 @@ import ( "encoding/json" goerrors "errors" "io" + "log/slog" "net/http" "reflect" @@ -28,20 +29,18 @@ func writeJSONResponse(w http.ResponseWriter, r *http.Request, code int, payload response, err := json.Marshal(payload) if err != nil { // Headers already sent, can't change status code - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(r.Context(), + "Failed to marshal JSON response payload", logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(code), - ).WithError(err).Error("Failed to marshal JSON response payload") + logger.HTTPStatusCode(code), "error", err) return } if _, err := w.Write(response); err != nil { // Writing failed, nothing we can do at this point - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(r.Context(), + "Failed to write JSON response body", logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(code), - ).WithError(err).Error("Failed to write JSON response body") + logger.HTTPStatusCode(code), "error", err) return } } @@ -85,15 +84,15 @@ func handleError(r *http.Request, w http.ResponseWriter, err *errors.ServiceErro // Log with RFC 9457 code format if err.HTTPCode >= 400 && err.HTTPCode <= 499 { - logger.With(r.Context(), - "code", err.RFC9457Code, + slog.InfoContext(r.Context(), + "Client error response", "code", err.RFC9457Code, "http_code", err.HTTPCode, - "reason", err.Reason).Info("Client error response") + "reason", err.Reason) } else { - logger.With(r.Context(), - "code", err.RFC9457Code, + slog.ErrorContext(r.Context(), + "Server error response", "code", err.RFC9457Code, "http_code", err.HTTPCode, - "reason", err.Reason).Error("Server error response") + "reason", err.Reason) } response.WriteProblemDetailsResponse(w, r, err.HTTPCode, err.AsProblemDetails(instance, traceID)) diff --git a/pkg/handlers/metadata.go b/pkg/handlers/metadata.go index e41b0bb2..50474a23 100755 --- a/pkg/handlers/metadata.go +++ b/pkg/handlers/metadata.go @@ -18,6 +18,7 @@ package handlers import ( "encoding/json" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" @@ -45,10 +46,9 @@ func (h MetadataHandler) Get(w http.ResponseWriter, r *http.Request) { } data, err := json.Marshal(body) if err != nil { - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), - logger.HTTPMethod(r.Method), - ).WithError(err).Error("Failed to marshal metadata response") + slog.ErrorContext(r.Context(), + "Failed to marshal metadata response", logger.HTTPPath(r.URL.Path), + logger.HTTPMethod(r.Method), "error", err) api.SendPanic(w, r) return } @@ -56,10 +56,9 @@ func (h MetadataHandler) Get(w http.ResponseWriter, r *http.Request) { // Send the response: _, err = w.Write(data) if err != nil { - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), - logger.HTTPMethod(r.Method), - ).WithError(err).Error("Failed to send metadata response body") + slog.ErrorContext(r.Context(), + "Failed to send metadata response body", logger.HTTPPath(r.URL.Path), + logger.HTTPMethod(r.Method), "error", err) return } } diff --git a/pkg/handlers/openapi.go b/pkg/handlers/openapi.go index ed037832..f0c5ea34 100755 --- a/pkg/handlers/openapi.go +++ b/pkg/handlers/openapi.go @@ -4,6 +4,7 @@ import ( "context" "embed" "io/fs" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api/openapi" @@ -38,7 +39,7 @@ func NewOpenAPIHandler() (*OpenAPIHandler, error) { err, ) } - logger.Info(ctx, "Loaded fully resolved OpenAPI specification from embedded pkg/api/openapi/api/openapi.yaml") + slog.InfoContext(ctx, "Loaded fully resolved OpenAPI specification from embedded pkg/api/openapi/api/openapi.yaml") // Load the OpenAPI UI HTML content uiContent, err := fs.ReadFile(openapiui, "openapi-ui.html") @@ -48,7 +49,7 @@ func NewOpenAPIHandler() (*OpenAPIHandler, error) { err, ) } - logger.Info(ctx, "Loaded OpenAPI UI HTML from embedded file") + slog.InfoContext(ctx, "Loaded OpenAPI UI HTML from embedded file") return &OpenAPIHandler{ openAPIDefinitions: data, @@ -61,11 +62,10 @@ func (h *OpenAPIHandler) GetOpenAPI(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) if _, err := w.Write(h.openAPIDefinitions); err != nil { // Response already committed, can't report error - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(r.Context(), + "Failed to write OpenAPI specification response", logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(http.StatusOK), - ).WithError(err).Error("Failed to write OpenAPI specification response") + logger.HTTPStatusCode(http.StatusOK), "error", err) return } } @@ -75,11 +75,10 @@ func (h *OpenAPIHandler) GetOpenAPIUI(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) if _, err := w.Write(h.uiContent); err != nil { // Response already committed, can't report error - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(r.Context(), + "Failed to write OpenAPI UI response", logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(http.StatusOK), - ).WithError(err).Error("Failed to write OpenAPI UI response") + logger.HTTPStatusCode(http.StatusOK), "error", err) return } } diff --git a/pkg/handlers/resource_status_handler.go b/pkg/handlers/resource_status_handler.go index 173d6336..e0ce5482 100644 --- a/pkg/handlers/resource_status_handler.go +++ b/pkg/handlers/resource_status_handler.go @@ -2,6 +2,7 @@ package handlers import ( "context" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api/openapi" @@ -72,6 +73,7 @@ func (h *ResourceStatusHandler) Create(w http.ResponseWriter, r *http.Request) { handleError(r, w, svcErr) return } + r = r.WithContext(logger.WithAdapter(r.Context(), req.Adapter)) id := r.PathValue("id") if svcErr := h.verifyResource(r, id); svcErr != nil { @@ -125,7 +127,7 @@ func (h *ResourceStatusHandler) listStatuses( for _, as := range adapterStatuses { presented, presErr := presenters.PresentAdapterStatus(as) if presErr != nil { - logger.WithError(ctx, presErr).Error("Failed to present adapter status") + slog.ErrorContext(ctx, "Failed to present adapter status", "error", presErr) return nil, errors.GeneralError("Failed to present adapter status") } items = append(items, presented) @@ -146,7 +148,7 @@ func (h *ResourceStatusHandler) processStatus( ) (interface{}, *errors.ServiceError) { newStatus, convErr := presenters.ConvertAdapterStatus(h.descriptor.Kind, resourceID, req) if convErr != nil { - logger.WithError(ctx, convErr).Error("Failed to convert adapter status") + slog.ErrorContext(ctx, "Failed to convert adapter status", "error", convErr) return nil, errors.GeneralError("Failed to convert adapter status") } @@ -163,7 +165,7 @@ func (h *ResourceStatusHandler) processStatus( status, presErr := presenters.PresentAdapterStatus(adapterStatus) if presErr != nil { - logger.WithError(ctx, presErr).Error("Failed to present adapter status") + slog.ErrorContext(ctx, "Failed to present adapter status", "error", presErr) return nil, errors.GeneralError("Failed to present adapter status") } return &status, nil diff --git a/pkg/handlers/resource_status_handler_test.go b/pkg/handlers/resource_status_handler_test.go index c60096b7..2c32ac40 100644 --- a/pkg/handlers/resource_status_handler_test.go +++ b/pkg/handlers/resource_status_handler_test.go @@ -1,7 +1,10 @@ package handlers import ( + "bytes" + "context" "encoding/json" + "log/slog" "net/http" "net/http/httptest" "strings" @@ -9,17 +12,91 @@ import ( "time" . "github.com/onsi/gomega" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "go.uber.org/mock/gomock" "gorm.io/datatypes" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api/openapi" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/services" ) const testChannelID = "ch-1" +func TestStatusHandlers_AdapterContextReachesServiceAndErrorResponse(t *testing.T) { + for _, route := range []string{"entity", "root"} { + t.Run(route, func(t *testing.T) { + var output bytes.Buffer + previous := slog.Default() + slog.SetDefault(logger.NewLogger("test", logger.HandlerConfig{ + Level: slog.LevelInfo, Format: hfl.FormatJSON, Output: &output, + })) + t.Cleanup(func() { slog.SetDefault(previous) }) + ctrl := gomock.NewController(t) + resourceSvc := services.NewMockResourceService(ctrl) + adapterSvc := services.NewMockAdapterStatusService(ctrl) + resource := &api.Resource{Kind: "Channel"} + resource.ID = testChannelID + resourceSvc.EXPECT().ProcessAdapterStatus( + gomock.Any(), resource.Kind, resource.ID, gomock.Any(), + ).DoAndReturn(func( + ctx context.Context, _, _ string, _ *api.AdapterStatus, + ) (*api.AdapterStatus, *errors.ServiceError) { + if adapter, _ := hfl.Get(ctx, logger.AdapterKey); adapter != "adapter1" { + t.Errorf("service adapter = %q, want adapter1", adapter) + } + if requestID, _ := logger.GetRequestID(ctx); requestID != "request-1" { + t.Errorf("service request ID = %q, want request-1", requestID) + } + return nil, errors.GeneralError("test failure") + }) + body := openapi.AdapterStatusCreateRequest{ + Adapter: "adapter1", ObservedGeneration: 1, ObservedTime: time.Now().UTC(), + Conditions: []openapi.ConditionRequest{ + {Type: "Available", Status: openapi.AdapterConditionStatusTrue}, + {Type: "Applied", Status: openapi.AdapterConditionStatusTrue}, + {Type: "Health", Status: openapi.AdapterConditionStatusTrue}, + }, + } + bodyJSON, err := json.Marshal(body) + if err != nil { + t.Fatal(err) + } + parent := hfl.Set(t.Context(), logger.ReqIDKey, "request-1") + parent = hfl.WithTraceID(parent, "trace-1") + req := httptest.NewRequest(http.MethodPut, "/statuses", bytes.NewReader(bodyJSON)).WithContext(parent) + req.SetPathValue("id", testChannelID) + res := httptest.NewRecorder() + if route == "entity" { + resourceSvc.EXPECT().Get(gomock.Any(), resource.Kind, resource.ID).Return(resource, nil) + NewResourceStatusHandler(channelDescriptor, resourceSvc, adapterSvc).Create(res, req) + } else { + resourceSvc.EXPECT().GetByID(gomock.Any(), resource.ID).Return(resource, nil) + NewRootResourceHandler(resourceSvc, adapterSvc, nil).CreateStatus(res, req) + } + if res.Code != http.StatusInternalServerError { + t.Fatalf("HTTP status = %d, want 500", res.Code) + } + var record map[string]any + if err := json.Unmarshal(output.Bytes(), &record); err != nil { + t.Fatal(err) + } + for key, want := range map[string]string{ + "adapter": "adapter1", "request_id": "request-1", "trace_id": "trace-1", + } { + if record[key] != want { + t.Errorf("error log %s = %v, want %q", key, record[key], want) + } + } + if _, ok := hfl.Get(parent, logger.AdapterKey); ok { + t.Error("handler must not modify the caller's context") + } + }) + } +} + func newTestResourceStatusHandler( ctrl *gomock.Controller, ) (*ResourceStatusHandler, *services.MockResourceService, *services.MockAdapterStatusService) { diff --git a/pkg/handlers/root_resource_handler.go b/pkg/handlers/root_resource_handler.go index 8401ea0d..e361b778 100644 --- a/pkg/handlers/root_resource_handler.go +++ b/pkg/handlers/root_resource_handler.go @@ -2,6 +2,7 @@ package handlers import ( "fmt" + "log/slog" "net/http" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api/openapi" @@ -247,7 +248,7 @@ func (h *RootResourceHandler) ListStatuses(w http.ResponseWriter, r *http.Reques for _, as := range statuses { presented, presErr := presenters.PresentAdapterStatus(as) if presErr != nil { - logger.WithError(ctx, presErr).Error("Failed to present adapter status") + slog.ErrorContext(ctx, "Failed to present adapter status", "error", presErr) handleError(r, w, errors.GeneralError("Failed to present adapter status")) return } @@ -277,6 +278,7 @@ func (h *RootResourceHandler) CreateStatus(w http.ResponseWriter, r *http.Reques handleError(r, w, svcErr) return } + r = r.WithContext(logger.WithAdapter(r.Context(), req.Adapter)) ctx := r.Context() id := r.PathValue("id") @@ -288,7 +290,7 @@ func (h *RootResourceHandler) CreateStatus(w http.ResponseWriter, r *http.Reques newStatus, convErr := presenters.ConvertAdapterStatus(resource.Kind, id, &req) if convErr != nil { - logger.WithError(ctx, convErr).Error("Failed to convert adapter status") + slog.ErrorContext(ctx, "Failed to convert adapter status", "error", convErr) handleError(r, w, errors.GeneralError("Failed to convert adapter status")) return } @@ -306,7 +308,7 @@ func (h *RootResourceHandler) CreateStatus(w http.ResponseWriter, r *http.Reques status, presErr := presenters.PresentAdapterStatus(adapterStatus) if presErr != nil { - logger.WithError(ctx, presErr).Error("Failed to present adapter status") + slog.ErrorContext(ctx, "Failed to present adapter status", "error", presErr) handleError(r, w, errors.GeneralError("Failed to present adapter status")) return } diff --git a/pkg/health/handler.go b/pkg/health/handler.go index 87d13a65..55e3722b 100644 --- a/pkg/health/handler.go +++ b/pkg/health/handler.go @@ -4,11 +4,11 @@ import ( "context" "encoding/json" "errors" + "log/slog" "net/http" "time" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // Handler provides HTTP handlers for health checks @@ -79,7 +79,7 @@ func (h *Handler) ReadinessHandler(w http.ResponseWriter, r *http.Request) { if pingCtx.Err() == context.DeadlineExceeded || errors.Is(err, context.DeadlineExceeded) { reason = "database ping timeout" } - logger.WithError(r.Context(), err).Warn("Readiness check: database ping failed") + slog.WarnContext(r.Context(), "Readiness check: database ping failed", "error", err) w.WriteHeader(http.StatusServiceUnavailable) json.NewEncoder(w).Encode(map[string]string{ //nolint:errcheck // best-effort response after header is written "status": "not_ready", diff --git a/pkg/logger/context.go b/pkg/logger/context.go index a9ee3244..3f1f206e 100644 --- a/pkg/logger/context.go +++ b/pkg/logger/context.go @@ -5,58 +5,32 @@ import ( "fmt" "github.com/google/uuid" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" ) -// contextKey is an unexported type for keys defined in this package. -// This prevents collisions with keys defined in other packages. -type contextKey string +// Context keys for API-specific correlation fields. Trace, span, resource type, +// and resource ID keys are owned by the shared logger package. +var ReqIDKey = hfl.NewKey[string](FieldRequestID) -// Context keys for storing correlation fields -const ( - ReqIDKey contextKey = "request_id" - TraceIDCtxKey contextKey = "trace_id" - SpanIDCtxKey contextKey = "span_id" - ClusterIDCtxKey contextKey = "cluster_id" - ResourceTypeCtxKey contextKey = "resource_type" - ResourceIDCtxKey contextKey = "resource_id" -) +// AdapterKey identifies the adapter whose report is being processed. +var AdapterKey = hfl.NewKey[string](FieldAdapter) + +// WithAdapter derives a context carrying adapter identity without losing request correlation. +func WithAdapter(ctx context.Context, adapter string) context.Context { + return hfl.Set(ctx, AdapterKey, adapter) +} // HTTP header names const ( ReqIDHeader = "X-Request-ID" ) -// WithTraceID adds trace ID to context -func WithTraceID(ctx context.Context, traceID string) context.Context { - return context.WithValue(ctx, TraceIDCtxKey, traceID) -} - -// WithSpanID adds span ID to context -func WithSpanID(ctx context.Context, spanID string) context.Context { - return context.WithValue(ctx, SpanIDCtxKey, spanID) -} - -// WithClusterID adds cluster ID to context -func WithClusterID(ctx context.Context, clusterID string) context.Context { - return context.WithValue(ctx, ClusterIDCtxKey, clusterID) -} - -// WithResourceType adds resource type to context -func WithResourceType(ctx context.Context, resourceType string) context.Context { - return context.WithValue(ctx, ResourceTypeCtxKey, resourceType) -} - -// WithResourceID adds resource ID to context -func WithResourceID(ctx context.Context, resourceID string) context.Context { - return context.WithValue(ctx, ResourceIDCtxKey, resourceID) -} - // WithRequestID adds request ID to context // If request ID already exists in context, it returns the context unchanged // Otherwise, it generates a new UUID v7 and adds it to the context // Returns an error if UUID generation fails (extremely unlikely in practice) func WithRequestID(ctx context.Context) (context.Context, error) { - if ctx.Value(ReqIDKey) != nil { + if _, ok := hfl.Get(ctx, ReqIDKey); ok { return ctx, nil } @@ -65,60 +39,20 @@ func WithRequestID(ctx context.Context) (context.Context, error) { return ctx, fmt.Errorf("failed to generate request ID: %w", err) } - return context.WithValue(ctx, ReqIDKey, reqID.String()), nil + return hfl.Set(ctx, ReqIDKey, reqID.String()), nil } // GetRequestID retrieves request ID from context func GetRequestID(ctx context.Context) (string, bool) { - reqID, ok := ctx.Value(ReqIDKey).(string) - return reqID, ok + return hfl.Get(ctx, ReqIDKey) } -// GetTraceID retrieves trace ID from context -func GetTraceID(ctx context.Context) (string, bool) { - traceID, ok := ctx.Value(TraceIDCtxKey).(string) - return traceID, ok -} - -// GetSpanID retrieves span ID from context -func GetSpanID(ctx context.Context) (string, bool) { - spanID, ok := ctx.Value(SpanIDCtxKey).(string) - return spanID, ok -} - -// GetClusterID retrieves cluster ID from context -func GetClusterID(ctx context.Context) (string, bool) { - clusterID, ok := ctx.Value(ClusterIDCtxKey).(string) - return clusterID, ok -} - -// GetResourceType retrieves resource type from context -func GetResourceType(ctx context.Context) (string, bool) { - resourceType, ok := ctx.Value(ResourceTypeCtxKey).(string) - return resourceType, ok -} - -// GetResourceID retrieves resource ID from context -func GetResourceID(ctx context.Context) (string, bool) { - resourceID, ok := ctx.Value(ResourceIDCtxKey).(string) - return resourceID, ok -} - -// ContextField defines metadata for a string-type context log field -type ContextField struct { - Getter func(context.Context) (string, bool) - Key contextKey - Name string -} - -// ContextFieldsRegistry defines all string-type context fields for logging -// This is the single source of truth for string field management -// Fields are ordered as per HyperFleet Logging Specification (docs/logging.md:384) -var ContextFieldsRegistry = []ContextField{ - {GetRequestID, ReqIDKey, "request_id"}, - {GetTraceID, TraceIDCtxKey, "trace_id"}, - {GetSpanID, SpanIDCtxKey, "span_id"}, - {GetClusterID, ClusterIDCtxKey, "cluster_id"}, - {GetResourceType, ResourceTypeCtxKey, "resource_type"}, - {GetResourceID, ResourceIDCtxKey, "resource_id"}, +// ContextFields returns API-specific fields for the shared handler. Standard +// correlation fields (trace_id, span_id, resource_type, resource_id) are +// registered by hyperfleet-logger itself. +func ContextFields() []hfl.ContextField { + return []hfl.ContextField{ + hfl.StringField(ReqIDKey), + hfl.StringField(AdapterKey), + } } diff --git a/pkg/logger/fields.go b/pkg/logger/fields.go index ea75dec3..88e30f1b 100644 --- a/pkg/logger/fields.go +++ b/pkg/logger/fields.go @@ -4,32 +4,23 @@ package logger // These constants provide type safety and prevent typos when adding temporary fields to logs. // // Usage: -// logger.With(ctx, logger.FieldBindAddress, addr).Info("Server starting") +// slog.InfoContext(ctx, "Server starting", logger.FieldBindAddress, addr) // -// For high-frequency fields (>10 occurrences), use helper functions instead (e.g., WithError). +// For high-frequency fields (>10 occurrences), use the shared context helpers instead. // Server/Config related fields const ( FieldBindAddress = "bind_address" - FieldEnvironment = "environment" FieldLogLevel = "level" FieldLogFormat = "format" FieldLogOutput = "output" ) -// Resource related fields -const ( - FieldNodePoolID = "nodepool_id" - // Note: cluster_id, resource_type, resource_id are context fields (see context.go) -) - // Database related fields const ( - FieldMigrationID = "migration_id" // FieldConnectionString - WARNING: Always sanitize connection strings before logging // to prevent exposing passwords. Never log raw connection strings. FieldConnectionString = "connection_string" - FieldTable = "table" FieldChannel = "channel" FieldLockID = "lock_id" FieldLockType = "lock_type" @@ -39,14 +30,12 @@ const ( // OpenTelemetry related fields const ( - FieldOTelEnabled = "otel_enabled" - FieldSamplingRate = "sampling_rate" - FieldExporterEndpoint = "exporter_endpoint" - FieldHyperfleetTracingEnabled = "hyperfleet_tracing_enabled" - FieldServiceName = "service_name" - FieldProtocol = "protocol" - FieldSampler = "sampler" - FieldServiceVersion = "service_version" + FieldOTelEnabled = "otel_enabled" + FieldSamplingRate = "sampling_rate" + FieldServiceName = "service_name" + FieldProtocol = "protocol" + FieldSampler = "sampler" + FieldServiceVersion = "service_version" ) // Schema related fields @@ -56,16 +45,10 @@ const ( // Generic fields const ( + FieldRequestID = "request_id" FieldAdapter = "adapter" FieldErrorCode = "error_code" - FieldFlag = "flag" FieldData = "data" ) -// Endpoint related fields (used in handlers) -const ( - FieldEndpoint = "endpoint" -) - // Note: HTTP-related field constants are defined in http.go -// Note: For error field, use WithError(ctx, err) helper function instead of FieldError constant diff --git a/pkg/logger/gorm_logger.go b/pkg/logger/gorm_logger.go index 407995f4..5577d34a 100644 --- a/pkg/logger/gorm_logger.go +++ b/pkg/logger/gorm_logger.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "log/slog" "time" gormlogger "gorm.io/gorm/logger" @@ -30,19 +31,19 @@ func (l *GormLogger) LogMode(level gormlogger.LogLevel) gormlogger.Interface { func (l *GormLogger) Info(ctx context.Context, msg string, data ...interface{}) { if l.logLevel >= gormlogger.Info { - With(ctx, "gorm_info", formatMessage(msg, data)).Info("GORM info") + slog.InfoContext(ctx, "GORM info", "gorm_info", formatMessage(msg, data)) } } func (l *GormLogger) Warn(ctx context.Context, msg string, data ...interface{}) { if l.logLevel >= gormlogger.Warn { - With(ctx, "gorm_warn", formatMessage(msg, data)).Warn("GORM warning") + slog.WarnContext(ctx, "GORM warning", "gorm_warn", formatMessage(msg, data)) } } func (l *GormLogger) Error(ctx context.Context, msg string, data ...interface{}) { if l.logLevel >= gormlogger.Error { - With(ctx, "gorm_error", formatMessage(msg, data)).Error("GORM error") + slog.ErrorContext(ctx, "GORM error", "gorm_error", formatMessage(msg, data)) } } @@ -61,27 +62,27 @@ func (l *GormLogger) Trace( switch { case err != nil && l.logLevel >= gormlogger.Error && !errors.Is(err, gormlogger.ErrRecordNotFound): - With(ctx, - "error", err.Error(), + slog.ErrorContext(ctx, "GORM query error", + "error", err, "duration_ms", float64(elapsed.Nanoseconds())/1e6, "rows", rows, "sql", sql, - ).Error("GORM query error") + ) case elapsed > l.slowThreshold && l.slowThreshold != 0 && l.logLevel >= gormlogger.Warn: - With(ctx, + slog.WarnContext(ctx, "GORM slow query", "duration_ms", float64(elapsed.Nanoseconds())/1e6, "threshold_ms", float64(l.slowThreshold.Nanoseconds())/1e6, "rows", rows, "sql", sql, - ).Warn("GORM slow query") + ) case l.logLevel >= gormlogger.Info: - With(ctx, + slog.InfoContext(ctx, "GORM query", "duration_ms", float64(elapsed.Nanoseconds())/1e6, "rows", rows, "sql", sql, - ).Info("GORM query") + ) } } diff --git a/pkg/logger/handler.go b/pkg/logger/handler.go new file mode 100644 index 00000000..c087047d --- /dev/null +++ b/pkg/logger/handler.go @@ -0,0 +1,48 @@ +package logger + +import ( + "context" + "io" + "log/slog" + + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" +) + +// Component is the logging component identity for HyperFleet API. +const Component = "api" + +// HandlerConfig configures the API-owned extensions to the shared handler. +// An empty Hostname uses hyperfleet-logger's OS hostname discovery. +type HandlerConfig struct { + Output io.Writer + Hostname string + Level slog.Level + Format hfl.Format +} + +// NewHandler builds a shared HyperFleet logging handler with API correlation +// fields and the API stack-trace policy. +func NewHandler(version string, cfg HandlerConfig) slog.Handler { + opts := []hfl.Option{ + hfl.WithLevel(cfg.Level), + hfl.WithFormat(cfg.Format), + hfl.WithOutput(cfg.Output), + hfl.WithContextFields(ContextFields()...), + hfl.WithSanitize(), + } + // Preserve the previous handlers: JSON captures every ERROR stack; + // text does not automatically capture stacks. + if cfg.Format == hfl.FormatJSON { + opts = append(opts, hfl.WithStackTrace(func(context.Context, slog.Record) bool { return true })) + } + if cfg.Hostname != "" { + opts = append(opts, hfl.WithHostname(cfg.Hostname)) + } + return hfl.NewHandler(Component, version, opts...) +} + +// NewLogger returns an isolated logger. Callers that require process-wide +// logging should install it with slog.SetDefault in their composition root. +func NewLogger(version string, cfg HandlerConfig) *slog.Logger { + return slog.New(NewHandler(version, cfg)) +} diff --git a/pkg/logger/handler_test.go b/pkg/logger/handler_test.go new file mode 100644 index 00000000..497964b1 --- /dev/null +++ b/pkg/logger/handler_test.go @@ -0,0 +1,91 @@ +package logger + +import ( + "bytes" + "encoding/json" + "log/slog" + "strings" + "testing" + + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" +) + +func TestHandlerAddsAPICorrelationFields(t *testing.T) { + var output bytes.Buffer + ctx := hfl.WithTraceID(t.Context(), "trace-1") + ctx = hfl.WithSpanID(ctx, "span-1") + ctx = hfl.WithResourceType(ctx, "Cluster") + ctx = hfl.WithResourceID(ctx, "cluster-1") + ctx, err := WithRequestID(ctx) + if err != nil { + t.Fatal(err) + } + + NewLogger("test-version", HandlerConfig{ + Level: slog.LevelInfo, Format: hfl.FormatJSON, Output: &output, Hostname: "test-host", + }).InfoContext(ctx, "cluster updated") + + var record map[string]any + if err := json.Unmarshal(output.Bytes(), &record); err != nil { + t.Fatal(err) + } + for key, want := range map[string]string{ + "component": Component, + "version": "test-version", + "hostname": "test-host", + "trace_id": "trace-1", + "span_id": "span-1", + "resource_type": "Cluster", + "resource_id": "cluster-1", + } { + if got := record[key]; got != want { + t.Errorf("%s = %v, want %q", key, got, want) + } + } + if _, ok := record["request_id"].(string); !ok { + t.Errorf("request_id = %T, want string", record["request_id"]) + } +} + +func TestHandlerSanitizesText(t *testing.T) { + var output bytes.Buffer + log := NewLogger("test", HandlerConfig{ + Level: slog.LevelInfo, Format: hfl.FormatText, Output: &output, Hostname: "test-host", + }) + log.ErrorContext(t.Context(), "expected\nerror") + if strings.Contains(output.String(), "expected\nerror") { + t.Fatal("text output must sanitize embedded control characters") + } +} + +func TestHandlerPreservesStackCaptureByFormat(t *testing.T) { + for _, format := range []struct { + name string + value hfl.Format + }{ + {name: "json", value: hfl.FormatJSON}, + {name: "text", value: hfl.FormatText}, + } { + for _, configured := range []slog.Level{slog.LevelDebug, slog.LevelInfo, slog.LevelError} { + for _, emitted := range []slog.Level{slog.LevelInfo, slog.LevelWarn, slog.LevelError, slog.LevelError + 4} { + t.Run(format.name+"/"+configured.String()+"/"+emitted.String(), func(t *testing.T) { + var output bytes.Buffer + NewLogger("test", HandlerConfig{ + Level: configured, Format: format.value, Output: &output, + }).Log(t.Context(), emitted, "test record") + if emitted < configured { + if output.Len() != 0 { + t.Fatal("disabled records must not be emitted") + } + return + } + hasStack := bytes.Contains(output.Bytes(), []byte("stack_trace")) + wantStack := format.value == hfl.FormatJSON && emitted >= slog.LevelError + if hasStack != wantStack { + t.Errorf("stack present = %v, want %v: %s", hasStack, wantStack, output.String()) + } + }) + } + } + } +} diff --git a/pkg/logger/http.go b/pkg/logger/http.go index 06725949..da177bc8 100644 --- a/pkg/logger/http.go +++ b/pkg/logger/http.go @@ -7,34 +7,34 @@ import ( // HTTP field name constants const ( - FieldHTTPMethod = "method" - FieldHTTPPath = "path" - FieldHTTPStatusCode = "status_code" - FieldHTTPDuration = "duration_ms" - FieldHTTPUserAgent = "user_agent" + fieldHTTPMethod = "method" + fieldHTTPPath = "path" + fieldHTTPStatusCode = "status_code" + fieldHTTPDuration = "duration_ms" + fieldHTTPUserAgent = "user_agent" ) // HTTPMethod returns a slog attribute for HTTP method func HTTPMethod(method string) slog.Attr { - return slog.String(FieldHTTPMethod, method) + return slog.String(fieldHTTPMethod, method) } // HTTPPath returns a slog attribute for HTTP path func HTTPPath(path string) slog.Attr { - return slog.String(FieldHTTPPath, path) + return slog.String(fieldHTTPPath, path) } // HTTPStatusCode returns a slog attribute for HTTP status code func HTTPStatusCode(code int) slog.Attr { - return slog.Int(FieldHTTPStatusCode, code) + return slog.Int(fieldHTTPStatusCode, code) } // HTTPDuration returns a slog attribute for HTTP request duration in milliseconds func HTTPDuration(d time.Duration) slog.Attr { - return slog.Int64(FieldHTTPDuration, d.Milliseconds()) + return slog.Int64(fieldHTTPDuration, d.Milliseconds()) } // HTTPUserAgent returns a slog attribute for HTTP user agent func HTTPUserAgent(ua string) slog.Attr { - return slog.String(FieldHTTPUserAgent, ua) + return slog.String(fieldHTTPUserAgent, ua) } diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go deleted file mode 100755 index 61164cde..00000000 --- a/pkg/logger/logger.go +++ /dev/null @@ -1,320 +0,0 @@ -package logger - -import ( - "context" - "fmt" - "io" - "log/slog" - "os" - "runtime" - "strings" - "sync/atomic" -) - -// LogFormat enumeration for output format -type LogFormat int - -const ( - // FormatText outputs logs in human-readable text format - FormatText LogFormat = iota - // FormatJSON outputs logs in JSON format for structured logging - FormatJSON -) - -// LogConfig holds the configuration for the logger -type LogConfig struct { - Output io.Writer - Component string - Version string - Hostname string - Level slog.Level - Format LogFormat -} - -// HyperFleetHandler implements slog.Handler interface -// Adds HyperFleet-specific fields: component, version, hostname, trace_id, span_id, etc. -type HyperFleetHandler struct { - handler slog.Handler - component string - version string - hostname string -} - -// NewHyperFleetHandler creates a HyperFleet logger handler -// Returns slog.Handler interface to support both HyperFleetHandler (JSON) and HyperFleetTextHandler (Text) -func NewHyperFleetHandler(cfg *LogConfig) slog.Handler { - if cfg.Format == FormatText { - return NewHyperFleetTextHandler(cfg.Output, cfg.Component, cfg.Version, cfg.Hostname, cfg.Level) - } - - var baseHandler slog.Handler - opts := &slog.HandlerOptions{ - Level: cfg.Level, - AddSource: true, - ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - if a.Key == slog.TimeKey { - return slog.Attr{Key: "timestamp", Value: a.Value} - } - if a.Key == slog.LevelKey { - if level, ok := a.Value.Any().(slog.Level); ok { - return slog.Attr{Key: "level", Value: slog.StringValue(strings.ToLower(level.String()))} - } - return slog.Attr{Key: "level", Value: slog.StringValue(strings.ToLower(fmt.Sprint(a.Value.Any())))} - } - if a.Key == slog.MessageKey { - return slog.Attr{Key: "message", Value: a.Value} - } - if a.Key == slog.SourceKey { - return a - } - return a - }, - } - - baseHandler = slog.NewJSONHandler(cfg.Output, opts) - - return &HyperFleetHandler{ - handler: baseHandler, - component: cfg.Component, - version: cfg.Version, - hostname: cfg.Hostname, - } -} - -// Handle implements slog.Handler interface -func (h *HyperFleetHandler) Handle(ctx context.Context, r slog.Record) error { - r.AddAttrs( - slog.String("component", h.component), - slog.String("version", h.version), - slog.String("hostname", h.hostname), - ) - - for _, field := range ContextFieldsRegistry { - if val, ok := field.Getter(ctx); ok { - r.AddAttrs(slog.String(field.Name, val)) - } - } - - if r.Level >= slog.LevelError { - stackTrace := captureStackTrace(4) - r.AddAttrs(slog.Any("stack_trace", stackTrace)) - } - - return h.handler.Handle(ctx, r) -} - -// Enabled implements slog.Handler interface -func (h *HyperFleetHandler) Enabled(ctx context.Context, level slog.Level) bool { - return h.handler.Enabled(ctx, level) -} - -// WithAttrs implements slog.Handler interface -func (h *HyperFleetHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - return &HyperFleetHandler{ - handler: h.handler.WithAttrs(attrs), - component: h.component, - version: h.version, - hostname: h.hostname, - } -} - -// WithGroup implements slog.Handler interface -func (h *HyperFleetHandler) WithGroup(name string) slog.Handler { - return &HyperFleetHandler{ - handler: h.handler.WithGroup(name), - component: h.component, - version: h.version, - hostname: h.hostname, - } -} - -func captureStackTrace(skip int) []string { - const maxFrames = 15 - pcs := make([]uintptr, maxFrames) - n := runtime.Callers(skip, pcs) - - frames := runtime.CallersFrames(pcs[:n]) - var stackTrace []string - for { - frame, more := frames.Next() - if !strings.Contains(frame.Function, "runtime.") && - !strings.Contains(frame.Function, "testing.") { - stackTrace = append(stackTrace, - fmt.Sprintf("%s:%d %s", frame.File, frame.Line, frame.Function)) - } - if !more { - break - } - } - return stackTrace -} - -var globalLogger atomic.Value // stores *slog.Logger - -// InitGlobalLogger initializes the global logger with the given configuration. -// This function is idempotent (safe to call multiple times). -// -// Concurrency note: This function uses atomic.Value without sync.Once intentionally. -// Current call sites are serialized (single-threaded main() and sync.Once in tests). -// If concurrent initialization occurs, the last Store() wins, which is acceptable. -// For stricter guarantees in future use cases, callers should wrap this with sync.Once -// or equivalent synchronization. -func InitGlobalLogger(cfg *LogConfig) { - if v := globalLogger.Load(); v != nil { - if logger, ok := v.(*slog.Logger); ok && logger != nil { - return - } - } - - handler := NewHyperFleetHandler(cfg) - logger := slog.New(handler) - globalLogger.Store(logger) - slog.SetDefault(logger) -} - -// ReconfigureGlobalLogger reconfigures the global logger with new configuration -// Unlike InitGlobalLogger, this can be called multiple times to update configuration -// This is useful when environment configuration is loaded after initial logger setup -func ReconfigureGlobalLogger(cfg *LogConfig) { - handler := NewHyperFleetHandler(cfg) - newLogger := slog.New(handler) - globalLogger.Store(newLogger) - slog.SetDefault(newLogger) -} - -// resetForTesting resets the global logger for testing purposes -// This function should ONLY be used in tests -func resetForTesting() { - globalLogger.Store((*slog.Logger)(nil)) -} - -// GetLogger returns the global logger instance -func GetLogger() *slog.Logger { - if v := globalLogger.Load(); v != nil { - if logger, ok := v.(*slog.Logger); ok && logger != nil { - return logger - } - } - return slog.Default() -} - -// ParseLogLevel converts string to slog.Level -func ParseLogLevel(level string) (slog.Level, error) { - switch strings.ToLower(strings.TrimSpace(level)) { - case "debug": - return slog.LevelDebug, nil - case "info": - return slog.LevelInfo, nil - case "warn", "warning": - return slog.LevelWarn, nil - case "error": - return slog.LevelError, nil - default: - return slog.LevelInfo, fmt.Errorf("unknown log level: %s (valid: debug, info, warn, error)", level) - } -} - -// ParseLogFormat converts string to LogFormat -func ParseLogFormat(format string) (LogFormat, error) { - switch strings.ToLower(strings.TrimSpace(format)) { - case "text": - return FormatText, nil - case "json": - return FormatJSON, nil - default: - return FormatText, fmt.Errorf("unknown log format: %s (valid: text, json)", format) - } -} - -// ParseLogOutput converts string to io.Writer -func ParseLogOutput(output string) (io.Writer, error) { - switch strings.ToLower(strings.TrimSpace(output)) { - case "stdout", "": - return os.Stdout, nil - case "stderr": - return os.Stderr, nil - default: - return nil, fmt.Errorf("unknown log output: %s (valid: stdout, stderr)", output) - } -} - -// Debug logs at Debug level with context fields only. -// For temporary fields, use With(). -func Debug(ctx context.Context, msg string) { - GetLogger().DebugContext(ctx, msg) -} - -// Info logs at Info level with context fields only. -// For temporary fields, use With(). -func Info(ctx context.Context, msg string) { - GetLogger().InfoContext(ctx, msg) -} - -// Warn logs at Warn level with context fields only. -// For temporary fields, use With(). -func Warn(ctx context.Context, msg string) { - GetLogger().WarnContext(ctx, msg) -} - -// Error logs at Error level with context fields only. -// For temporary fields, use With(). -func Error(ctx context.Context, msg string) { - GetLogger().ErrorContext(ctx, msg) -} - -// ContextLogger wraps a context with additional temporary key-value pairs for logging. -type ContextLogger struct { - ctx context.Context - logger *slog.Logger -} - -// With creates a new ContextLogger with temporary key-value pairs. -func With(ctx context.Context, args ...any) *ContextLogger { - return &ContextLogger{ - ctx: ctx, - logger: GetLogger().With(args...), - } -} - -// WithError is a convenience function for adding error field to logs. -func WithError(ctx context.Context, err error) *ContextLogger { - if err == nil { - return With(ctx) - } - return With(ctx, "error", err.Error()) -} - -// WithError adds an error field to the logger and can be chained. -func (l *ContextLogger) WithError(err error) *ContextLogger { - if err == nil { - return l - } - return &ContextLogger{ - ctx: l.ctx, - logger: l.logger.With("error", err.Error()), - } -} - -// With adds additional temporary fields to the logger and can be chained. -func (l *ContextLogger) With(args ...any) *ContextLogger { - return &ContextLogger{ - ctx: l.ctx, - logger: l.logger.With(args...), - } -} - -func (l *ContextLogger) Debug(msg string) { - l.logger.DebugContext(l.ctx, msg) -} - -func (l *ContextLogger) Info(msg string) { - l.logger.InfoContext(l.ctx, msg) -} - -func (l *ContextLogger) Warn(msg string) { - l.logger.WarnContext(l.ctx, msg) -} - -func (l *ContextLogger) Error(msg string) { - l.logger.ErrorContext(l.ctx, msg) -} diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go deleted file mode 100644 index a44b9465..00000000 --- a/pkg/logger/logger_test.go +++ /dev/null @@ -1,841 +0,0 @@ -package logger - -import ( - "bytes" - "context" - "encoding/json" - "log/slog" - "os" - "strings" - "testing" -) - -const ( - testMessage = "test message" -) - -// TestParseLogLevel tests log level parsing with various inputs -func TestParseLogLevel(t *testing.T) { - tests := []struct { - name string - input string - expected slog.Level - expectErr bool - }{ - {"debug", "debug", slog.LevelDebug, false}, - {"info", "info", slog.LevelInfo, false}, - {"warn", "warn", slog.LevelWarn, false}, - {"warning", "warning", slog.LevelWarn, false}, - {"error", "error", slog.LevelError, false}, - {"case insensitive", "DEBUG", slog.LevelDebug, false}, - {"with whitespace", " info ", slog.LevelInfo, false}, - {"invalid", "invalid", slog.LevelInfo, true}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - level, err := ParseLogLevel(tt.input) - if tt.expectErr { - if err == nil { - t.Error("expected error, got nil") - } - if !strings.Contains(err.Error(), "unknown log level") { - t.Errorf("unexpected error message: %v", err) - } - } else { - if err != nil { - t.Errorf("unexpected error: %v", err) - } - if level != tt.expected { - t.Errorf("expected %v, got %v", tt.expected, level) - } - } - }) - } -} - -// TestParseLogFormat tests log format parsing with various inputs -func TestParseLogFormat(t *testing.T) { - tests := []struct { - name string - input string - expected LogFormat - expectErr bool - }{ - {"text", "text", FormatText, false}, - {"json", "json", FormatJSON, false}, - {"case insensitive", "JSON", FormatJSON, false}, - {"invalid", "invalid", FormatText, true}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - format, err := ParseLogFormat(tt.input) - if tt.expectErr { - if err == nil { - t.Error("expected error, got nil") - } - if !strings.Contains(err.Error(), "unknown log format") { - t.Errorf("unexpected error message: %v", err) - } - } else { - if err != nil { - t.Errorf("unexpected error: %v", err) - } - if format != tt.expected { - t.Errorf("expected %v, got %v", tt.expected, format) - } - } - }) - } -} - -// TestParseLogOutput tests log output parsing with various inputs -func TestParseLogOutput(t *testing.T) { - tests := []struct { - expected *os.File - name string - input string - expectErr bool - }{ - {name: "stdout", input: "stdout", expected: os.Stdout, expectErr: false}, - {name: "stderr", input: "stderr", expected: os.Stderr, expectErr: false}, - {name: "empty defaults to stdout", input: "", expected: os.Stdout, expectErr: false}, - {name: "invalid", input: "invalid", expected: nil, expectErr: true}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - output, err := ParseLogOutput(tt.input) - if tt.expectErr { - if err == nil { - t.Error("expected error, got nil") - } - if !strings.Contains(err.Error(), "unknown log output") { - t.Errorf("unexpected error message: %v", err) - } - } else { - if err != nil { - t.Errorf("unexpected error: %v", err) - } - if output != tt.expected { - t.Errorf("expected %v, got %v", tt.expected, output) - } - } - }) - } -} - -// TestBasicLogFormat tests basic log format output for both JSON and text formats -func TestBasicLogFormat(t *testing.T) { - tests := []struct { - name string - format LogFormat - }{ - {"JSON format", FormatJSON}, - {"Text format", FormatText}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: tt.format, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - - InitGlobalLogger(cfg) - ctx := context.Background() - With(ctx, "key", "value").Info(testMessage) - - output := buf.String() - if output == "" { - t.Fatal("expected log output, got none") - } - - if tt.format == FormatJSON { - // Parse the last JSON line (handles multi-line output like stack traces) - output = strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - // Check required fields - if logEntry["message"] != testMessage { - t.Errorf("expected message %q, got %v", testMessage, logEntry["message"]) - } - if logEntry["level"] != "info" { - t.Errorf("expected level 'info', got %v", logEntry["level"]) - } - if logEntry["component"] != "api" { - t.Errorf("expected component 'api', got %v", logEntry["component"]) - } - if logEntry["version"] != "test-version" { - t.Errorf("expected version 'test-version', got %v", logEntry["version"]) - } - if logEntry["hostname"] != "test-host" { - t.Errorf("expected hostname 'test-host', got %v", logEntry["hostname"]) - } - if logEntry["key"] != "value" { - t.Errorf("expected key 'value', got %v", logEntry["key"]) - } - } else { - // Text format - check for stable invariants only - if !strings.Contains(output, testMessage) { - t.Errorf("expected output to contain %q, got: %s", testMessage, output) - } - // Check for log level (case-insensitive) - outputLower := strings.ToLower(output) - if !strings.Contains(outputLower, "info") { - t.Errorf("expected output to contain log level 'info', got: %s", output) - } - } - }) - } -} - -// TestContextFields tests context field extraction for all supported fields -func TestContextFields(t *testing.T) { - tests := []struct { - name string - setupCtx func(context.Context) context.Context - fieldName string - fieldValue string - }{ - { - name: "trace_id", - setupCtx: func(ctx context.Context) context.Context { return WithTraceID(ctx, "trace-123") }, - fieldName: "trace_id", - fieldValue: "trace-123", - }, - { - name: "span_id", - setupCtx: func(ctx context.Context) context.Context { return WithSpanID(ctx, "span-456") }, - fieldName: "span_id", - fieldValue: "span-456", - }, - { - name: "request_id", - setupCtx: func(ctx context.Context) context.Context { - return context.WithValue(ctx, ReqIDKey, "req-789") - }, - fieldName: "request_id", - fieldValue: "req-789", - }, - { - name: "cluster_id", - setupCtx: func(ctx context.Context) context.Context { return WithClusterID(ctx, "cluster-abc") }, - fieldName: "cluster_id", - fieldValue: "cluster-abc", - }, - { - name: "resource_type", - setupCtx: func(ctx context.Context) context.Context { return WithResourceType(ctx, "managed-cluster") }, - fieldName: "resource_type", - fieldValue: "managed-cluster", - }, - { - name: "resource_id", - setupCtx: func(ctx context.Context) context.Context { return WithResourceID(ctx, "resource-xyz") }, - fieldName: "resource_id", - fieldValue: "resource-xyz", - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := tt.setupCtx(context.Background()) - Info(ctx, "test message") - - // Parse the last JSON line (handles multi-line output like stack traces) - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry[tt.fieldName] != tt.fieldValue { - t.Errorf("expected %s='%s', got %v", tt.fieldName, tt.fieldValue, logEntry[tt.fieldName]) - } - }) - } -} - -// TestContextFields_Multiple tests multiple context fields together -func TestContextFields_Multiple(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - - InitGlobalLogger(cfg) - ctx := context.Background() - ctx = WithTraceID(ctx, "trace-123") - ctx = WithSpanID(ctx, "span-456") - ctx = WithClusterID(ctx, "cluster-abc") - Info(ctx, "test message") - - // Parse the last JSON line (handles multi-line output like stack traces) - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["trace_id"] != "trace-123" { - t.Errorf("expected trace_id 'trace-123', got %v", logEntry["trace_id"]) - } - if logEntry["span_id"] != "span-456" { - t.Errorf("expected span_id 'span-456', got %v", logEntry["span_id"]) - } - if logEntry["cluster_id"] != "cluster-abc" { - t.Errorf("expected cluster_id 'cluster-abc', got %v", logEntry["cluster_id"]) - } -} - -// TestStackTrace tests stack trace capture for different log levels -func TestStackTrace(t *testing.T) { - tests := []struct { - logFunc func(context.Context, string) - name string - level slog.Level - expectStackTrace bool - }{ - {name: "error level has stack trace", level: slog.LevelError, logFunc: Error, expectStackTrace: true}, - {name: "info level no stack trace", level: slog.LevelInfo, logFunc: Info, expectStackTrace: false}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: tt.level, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - tt.logFunc(ctx, "test message") - - // Parse the last JSON line (handles multi-line output like stack traces) - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if tt.expectStackTrace { - if logEntry["stack_trace"] == nil { - t.Error("expected stack_trace field for error level") - } - // Verify stack trace is an array - stackTrace, ok := logEntry["stack_trace"].([]interface{}) - if !ok { - t.Fatalf("expected stack_trace to be array, got %T", logEntry["stack_trace"]) - } - if len(stackTrace) == 0 { - t.Error("expected stack_trace to have at least one frame") - } - } else if logEntry["stack_trace"] != nil { - t.Error("expected no stack_trace field for non-error level") - } - }) - } -} - -// TestLogLevelFiltering tests log level filtering -func TestLogLevelFiltering(t *testing.T) { - tests := []struct { - logFunc func(context.Context, string) - name string - configLevel slog.Level - shouldLog bool - }{ - {name: "debug filtered at info level", configLevel: slog.LevelInfo, logFunc: Debug, shouldLog: false}, - {name: "info enabled at info level", configLevel: slog.LevelInfo, logFunc: Info, shouldLog: true}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: tt.configLevel, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - tt.logFunc(ctx, "test message") - - if tt.shouldLog && buf.Len() == 0 { - t.Error("expected log output, got none") - } - if !tt.shouldLog && buf.Len() > 0 { - t.Errorf("expected no log output, got: %s", buf.String()) - } - }) - } -} - -// TestGetLogger_Uninitialized tests GetLogger with uninitialized global logger -func TestGetLogger_Uninitialized(t *testing.T) { - // Save and restore global logger - saved := globalLogger.Load() - defer func() { globalLogger.Store(saved) }() - - globalLogger.Store((*slog.Logger)(nil)) - logger := GetLogger() - - if logger == nil { - t.Error("expected GetLogger to return non-nil logger") - } - - // Should return default logger - if logger != slog.Default() { - t.Error("expected GetLogger to return slog.Default() when uninitialized") - } -} - -// TestConvenienceFunctions tests all convenience functions (Debug, Info, Warn, Error) -func TestConvenienceFunctions(t *testing.T) { - tests := []struct { - logFunc func(context.Context, string) - name string - expectedLvl string - level slog.Level - }{ - {name: "Debug", level: slog.LevelDebug, logFunc: Debug, expectedLvl: "debug"}, - {name: "Info", level: slog.LevelInfo, logFunc: Info, expectedLvl: "info"}, - {name: "Warn", level: slog.LevelWarn, logFunc: Warn, expectedLvl: "warn"}, - {name: "Error", level: slog.LevelError, logFunc: Error, expectedLvl: "error"}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: tt.level, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - tt.logFunc(ctx, "test message") - - // Parse the last JSON line (handles multi-line output like stack traces) - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["level"] != tt.expectedLvl { - t.Errorf("expected level '%s', got %v", tt.expectedLvl, logEntry["level"]) - } - if logEntry["message"] != "test message" { - t.Errorf("expected message 'test message', got %v", logEntry["message"]) - } - }) - } -} - -// TestWithError tests the WithError convenience function -func TestWithError(t *testing.T) { - tests := []struct { - err error - name string - expectedValue string - expectError bool - }{ - { - name: "non-nil error", - err: bytes.ErrTooLarge, - expectError: true, - expectedValue: "bytes.Buffer: too large", - }, - { - name: "nil error", - err: nil, - expectError: false, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - WithError(ctx, tt.err).Info("test message") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - // Verify message is always present - if logEntry["message"] != "test message" { - t.Errorf("expected message 'test message', got %v", logEntry["message"]) - } - - // Check error field presence - if tt.expectError { - if logEntry["error"] == nil { - t.Error("expected error field to be present") - } - if logEntry["error"] != tt.expectedValue { - t.Errorf("expected error '%s', got %v", tt.expectedValue, logEntry["error"]) - } - } else if logEntry["error"] != nil { - t.Errorf("expected no error field for nil error, got %v", logEntry["error"]) - } - }) - } -} - -// TestWithError_MethodChaining tests that WithError returns a ContextLogger for method chaining -func TestWithError_MethodChaining(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - testErr := bytes.ErrTooLarge - - // Test method chaining works at different log levels - WithError(ctx, testErr).Info("info message") - WithError(ctx, testErr).Warn("warn message") - WithError(ctx, testErr).Error("error message") - - output := buf.String() - if !strings.Contains(output, "info message") { - t.Error("expected output to contain 'info message'") - } - if !strings.Contains(output, "warn message") { - t.Error("expected output to contain 'warn message'") - } - if !strings.Contains(output, "error message") { - t.Error("expected output to contain 'error message'") - } -} - -// TestContextLogger_With_Single tests single With call -func TestContextLogger_With_Single(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - With(ctx, "user_id", "user123").With("action", "login").Info("User action") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["user_id"] != "user123" { - t.Errorf("expected user_id 'user123', got %v", logEntry["user_id"]) - } - if logEntry["action"] != "login" { - t.Errorf("expected action 'login', got %v", logEntry["action"]) - } - if logEntry["message"] != "User action" { - t.Errorf("expected message 'User action', got %v", logEntry["message"]) - } -} - -// TestContextLogger_With_Chaining tests multiple With calls chained together -func TestContextLogger_With_Chaining(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - With(ctx, "field1", "value1"). - With("field2", "value2"). - With("field3", "value3"). - Info("Test chaining") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["field1"] != "value1" { - t.Errorf("expected field1 'value1', got %v", logEntry["field1"]) - } - if logEntry["field2"] != "value2" { - t.Errorf("expected field2 'value2', got %v", logEntry["field2"]) - } - if logEntry["field3"] != "value3" { - t.Errorf("expected field3 'value3', got %v", logEntry["field3"]) - } -} - -// TestContextLogger_With_AndWithError tests combining With and WithError -func TestContextLogger_With_AndWithError(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - testErr := bytes.ErrTooLarge - With(ctx, "user_id", "user456"). - With("operation", "upload"). - WithError(testErr). - Error("Upload failed") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["user_id"] != "user456" { - t.Errorf("expected user_id 'user456', got %v", logEntry["user_id"]) - } - if logEntry["operation"] != "upload" { - t.Errorf("expected operation 'upload', got %v", logEntry["operation"]) - } - if logEntry["error"] != "bytes.Buffer: too large" { - t.Errorf("expected error 'bytes.Buffer: too large', got %v", logEntry["error"]) - } -} - -// TestContextLogger_With_Empty tests With with no arguments -func TestContextLogger_With_Empty(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - // With() with no arguments should still work - With(ctx, "field1", "value1").With().Info("Test empty With") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["field1"] != "value1" { - t.Errorf("expected field1 'value1', got %v", logEntry["field1"]) - } - if logEntry["message"] != "Test empty With" { - t.Errorf("expected message 'Test empty With', got %v", logEntry["message"]) - } -} - -// TestContextLogger_With_SlogAttr tests With combined with slog.Attr -func TestContextLogger_With_SlogAttr(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - With(ctx, - slog.String("string_field", "string_value"), - slog.Int("int_field", 42), - ).With( - slog.Bool("bool_field", true), - ).Info("Test slog.Attr") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["string_field"] != "string_value" { - t.Errorf("expected string_field 'string_value', got %v", logEntry["string_field"]) - } - // JSON numbers are float64 by default - if intField, ok := logEntry["int_field"].(float64); !ok || int(intField) != 42 { - t.Errorf("expected int_field 42, got %v", logEntry["int_field"]) - } - if logEntry["bool_field"] != true { - t.Errorf("expected bool_field true, got %v", logEntry["bool_field"]) - } -} - -// TestContextLogger_With_HTTPHelpers tests With combined with HTTP helper functions -func TestContextLogger_With_HTTPHelpers(t *testing.T) { - resetForTesting() - var buf bytes.Buffer - cfg := &LogConfig{ - Level: slog.LevelInfo, - Format: FormatJSON, - Output: &buf, - Component: "api", - Version: "test-version", - Hostname: "test-host", - } - InitGlobalLogger(cfg) - - ctx := context.Background() - With(ctx, - HTTPMethod("POST"), - HTTPPath("/api/v1/users"), - ).With( - HTTPStatusCode(201), - ).Info("HTTP request handled") - - // Parse the last JSON line - output := strings.TrimSpace(buf.String()) - lines := strings.Split(output, "\n") - lastLine := lines[len(lines)-1] - - var logEntry map[string]interface{} - if err := json.Unmarshal([]byte(lastLine), &logEntry); err != nil { - t.Fatalf("failed to parse JSON log: %v", err) - } - - if logEntry["method"] != "POST" { - t.Errorf("expected method 'POST', got %v", logEntry["method"]) - } - if logEntry["path"] != "/api/v1/users" { - t.Errorf("expected path '/api/v1/users', got %v", logEntry["path"]) - } - // JSON numbers are float64 by default - if statusCode, ok := logEntry["status_code"].(float64); !ok || int(statusCode) != 201 { - t.Errorf("expected status_code 201, got %v", logEntry["status_code"]) - } -} diff --git a/pkg/logger/requestid_middleware.go b/pkg/logger/requestid_middleware.go index 43752b46..fafe77c1 100644 --- a/pkg/logger/requestid_middleware.go +++ b/pkg/logger/requestid_middleware.go @@ -2,6 +2,7 @@ package logger import ( "fmt" + "log/slog" "net/http" ) @@ -11,7 +12,7 @@ func RequestIDMiddleware(handler http.Handler) http.Handler { ctx, err := WithRequestID(r.Context()) if err != nil { wrappedErr := fmt.Errorf("request ID middleware: %w", err) - WithError(r.Context(), wrappedErr).Error("Failed to generate request ID; continuing without it") + slog.ErrorContext(r.Context(), "Failed to generate request ID; continuing without it", "error", wrappedErr) ctx = r.Context() } diff --git a/pkg/logger/text_handler.go b/pkg/logger/text_handler.go deleted file mode 100644 index 575d0973..00000000 --- a/pkg/logger/text_handler.go +++ /dev/null @@ -1,134 +0,0 @@ -package logger - -import ( - "context" - "fmt" - "io" - "log/slog" - "runtime" - "strings" - "sync" - "time" -) - -// HyperFleetTextHandler implements the HyperFleet Logging Specification text format: -// {timestamp} {LEVEL} [{component}] [{version}] [{hostname}] {message} {key=value}... -// -// Example output: -// 2026-01-09T12:30:45Z INFO [hyperfleet-api] [v1.2.3] [pod-abc] Processing request request_id=xyz cluster_id=abc123 -type HyperFleetTextHandler struct { - w io.Writer - component string - version string - hostname string - attrs []slog.Attr - level slog.Level - mu sync.Mutex -} - -// NewHyperFleetTextHandler creates a new text handler conforming to HyperFleet Logging Specification -func NewHyperFleetTextHandler( - w io.Writer, component, version, hostname string, level slog.Level, -) *HyperFleetTextHandler { - return &HyperFleetTextHandler{ - w: w, - component: component, - version: version, - hostname: hostname, - level: level, - } -} - -// Enabled reports whether the handler handles records at the given level -func (h *HyperFleetTextHandler) Enabled(_ context.Context, level slog.Level) bool { - return level >= h.level -} - -func (h *HyperFleetTextHandler) Handle(ctx context.Context, r slog.Record) error { - var buf strings.Builder - - buf.WriteString(r.Time.Format(time.RFC3339)) - buf.WriteByte(' ') - buf.WriteString(strings.ToUpper(r.Level.String())) - buf.WriteByte(' ') - fmt.Fprintf(&buf, "[%s] [%s] [%s] ", h.component, h.version, h.hostname) - buf.WriteString(r.Message) - - for _, field := range ContextFieldsRegistry { - if val, ok := field.Getter(ctx); ok { - fmt.Fprintf(&buf, " %s=%s", field.Name, formatValue(val)) - } - } - - for _, attr := range h.attrs { - fmt.Fprintf(&buf, " %s=%s", attr.Key, formatValue(attr.Value.Any())) - } - - var stackTrace []string - r.Attrs(func(a slog.Attr) bool { - if a.Key == "stack_trace" { - if frames, ok := a.Value.Any().([]runtime.Frame); ok { - stackTrace = formatStackTrace(frames) - return true - } - } - fmt.Fprintf(&buf, " %s=%s", a.Key, formatValue(a.Value.Any())) - return true - }) - - buf.WriteByte('\n') - - if len(stackTrace) > 0 { - buf.WriteString(" stack_trace:\n") - for _, frame := range stackTrace { - fmt.Fprintf(&buf, " %s\n", frame) - } - } - - h.mu.Lock() - defer h.mu.Unlock() - _, err := h.w.Write([]byte(buf.String())) - return err -} - -func (h *HyperFleetTextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - newAttrs := make([]slog.Attr, len(h.attrs)+len(attrs)) - copy(newAttrs, h.attrs) - copy(newAttrs[len(h.attrs):], attrs) - - return &HyperFleetTextHandler{ - w: h.w, - component: h.component, - version: h.version, - hostname: h.hostname, - level: h.level, - attrs: newAttrs, - } -} - -// WithGroup returns a new handler with a group name -func (h *HyperFleetTextHandler) WithGroup(name string) slog.Handler { - // For simplicity, return self (groups not needed for HyperFleet spec) - return h -} - -func formatValue(v interface{}) string { - if v == nil { - return "null" - } - - str := fmt.Sprintf("%v", v) - if strings.ContainsAny(str, " \t\n\"") { - str = strings.ReplaceAll(str, `"`, `\"`) - return fmt.Sprintf(`"%s"`, str) - } - return str -} - -func formatStackTrace(frames []runtime.Frame) []string { - result := make([]string, 0, len(frames)) - for _, frame := range frames { - result = append(result, fmt.Sprintf("%s:%d %s", frame.File, frame.Line, frame.Function)) - } - return result -} diff --git a/pkg/logger/text_handler_test.go b/pkg/logger/text_handler_test.go deleted file mode 100644 index ef4a0adf..00000000 --- a/pkg/logger/text_handler_test.go +++ /dev/null @@ -1,264 +0,0 @@ -package logger - -import ( - "bytes" - "context" - "log/slog" - "strings" - "testing" -) - -// TestHyperFleetTextHandler_BasicFormat tests basic text output format -func TestHyperFleetTextHandler_BasicFormat(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - logger.InfoContext(ctx, "Test message", "key", "value") - - output := buf.String() - - // Check format: {timestamp} {LEVEL} [{component}] [{version}] [{hostname}] {message} {key=value}... - if !strings.Contains(output, "INFO") { - t.Errorf("expected uppercase level INFO, got: %s", output) - } - if !strings.Contains(output, "[hyperfleet-api]") { - t.Errorf("expected [hyperfleet-api], got: %s", output) - } - if !strings.Contains(output, "[v1.2.3]") { - t.Errorf("expected [v1.2.3], got: %s", output) - } - if !strings.Contains(output, "[test-host]") { - t.Errorf("expected [test-host], got: %s", output) - } - if !strings.Contains(output, "Test message") { - t.Errorf("expected 'Test message', got: %s", output) - } - if !strings.Contains(output, "key=value") { - t.Errorf("expected key=value, got: %s", output) - } -} - -// TestHyperFleetTextHandler_ContextFields tests context field extraction -func TestHyperFleetTextHandler_ContextFields(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - ctx = context.WithValue(ctx, ReqIDKey, "test-request-123") - ctx = context.WithValue(ctx, TraceIDCtxKey, "trace-456") - ctx = context.WithValue(ctx, SpanIDCtxKey, "span-789") - ctx = context.WithValue(ctx, ClusterIDCtxKey, "cluster-abc") - - logger := slog.New(handler) - logger.InfoContext(ctx, "Processing request") - - output := buf.String() - - if !strings.Contains(output, "request_id=test-request-123") { - t.Errorf("expected request_id=test-request-123, got: %s", output) - } - if !strings.Contains(output, "trace_id=trace-456") { - t.Errorf("expected trace_id=trace-456, got: %s", output) - } - if !strings.Contains(output, "span_id=span-789") { - t.Errorf("expected span_id=span-789, got: %s", output) - } - if !strings.Contains(output, "cluster_id=cluster-abc") { - t.Errorf("expected cluster_id=cluster-abc, got: %s", output) - } -} - -// TestHyperFleetTextHandler_SpecialCharacters tests value quoting for special characters -func TestHyperFleetTextHandler_SpecialCharacters(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - logger.InfoContext(ctx, "Test message", - "simple", "value", - "with_spaces", "hello world", - "with_quotes", `contains "quotes"`) - - output := buf.String() - - // Simple value without quotes - if !strings.Contains(output, "simple=value") { - t.Errorf("expected simple=value, got: %s", output) - } - - // Value with spaces should be quoted - if !strings.Contains(output, `with_spaces="hello world"`) { - t.Errorf("expected quoted value for spaces, got: %s", output) - } - - // Value with internal quotes should be escaped and quoted - hasQuotes := strings.Contains(output, `with_quotes="contains \"quotes\""`) || - strings.Contains(output, `with_quotes="contains \\\"quotes\\\""`) - if !hasQuotes { - t.Errorf("expected escaped quotes, got: %s", output) - } -} - -// TestHyperFleetTextHandler_LogLevels tests different log levels -func TestHyperFleetTextHandler_LogLevels(t *testing.T) { - tests := []struct { - logFunc func(*slog.Logger, context.Context, string) - name string - expectedLevel string - level slog.Level - shouldLog bool - }{ - { - name: "DEBUG enabled", level: slog.LevelDebug, - logFunc: func(l *slog.Logger, ctx context.Context, msg string) { l.DebugContext(ctx, msg) }, - expectedLevel: "DEBUG", shouldLog: true, - }, - { - name: "INFO enabled", level: slog.LevelInfo, - logFunc: func(l *slog.Logger, ctx context.Context, msg string) { l.InfoContext(ctx, msg) }, - expectedLevel: "INFO", shouldLog: true, - }, - { - name: "WARN enabled", level: slog.LevelWarn, - logFunc: func(l *slog.Logger, ctx context.Context, msg string) { l.WarnContext(ctx, msg) }, - expectedLevel: "WARN", shouldLog: true, - }, - { - name: "ERROR enabled", level: slog.LevelError, - logFunc: func(l *slog.Logger, ctx context.Context, msg string) { l.ErrorContext(ctx, msg) }, - expectedLevel: "ERROR", shouldLog: true, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", tt.level) - - ctx := context.Background() - logger := slog.New(handler) - tt.logFunc(logger, ctx, "Test message") - - output := buf.String() - - if tt.shouldLog && !strings.Contains(output, tt.expectedLevel) { - t.Errorf("expected level %s, got: %s", tt.expectedLevel, output) - } - }) - } -} - -// TestHyperFleetTextHandler_LevelFiltering tests log level filtering -func TestHyperFleetTextHandler_LevelFiltering(t *testing.T) { - var buf bytes.Buffer - // Set handler to INFO level - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - - // DEBUG should be filtered out - logger.DebugContext(ctx, "Debug message") - if buf.Len() > 0 { - t.Errorf("expected DEBUG to be filtered, got output: %s", buf.String()) - } - - // INFO should pass through - logger.InfoContext(ctx, "Info message") - if buf.Len() == 0 { - t.Error("expected INFO to be logged") - } -} - -// TestHyperFleetTextHandler_MessageOnly tests logging with message only (no attributes) -func TestHyperFleetTextHandler_MessageOnly(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - logger.InfoContext(ctx, "Simple message") - - output := buf.String() - - if !strings.Contains(output, "Simple message") { - t.Errorf("expected 'Simple message', got: %s", output) - } - // Should have system fields but no additional key=value pairs - if !strings.Contains(output, "[hyperfleet-api]") { - t.Errorf("expected system fields, got: %s", output) - } -} - -// TestHyperFleetTextHandler_MultipleAttributes tests logging with multiple attributes -func TestHyperFleetTextHandler_MultipleAttributes(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - logger.InfoContext(ctx, "Multiple attributes", - "attr1", "value1", - "attr2", 42, - "attr3", true) - - output := buf.String() - - if !strings.Contains(output, "attr1=value1") { - t.Errorf("expected attr1=value1, got: %s", output) - } - if !strings.Contains(output, "attr2=42") { - t.Errorf("expected attr2=42, got: %s", output) - } - if !strings.Contains(output, "attr3=true") { - t.Errorf("expected attr3=true, got: %s", output) - } -} - -// TestHyperFleetTextHandler_EmptyContext tests logging with empty context -func TestHyperFleetTextHandler_EmptyContext(t *testing.T) { - var buf bytes.Buffer - handler := NewHyperFleetTextHandler(&buf, "hyperfleet-api", "v1.2.3", "test-host", slog.LevelInfo) - - ctx := context.Background() - logger := slog.New(handler) - logger.InfoContext(ctx, "No context fields") - - output := buf.String() - - // Should not have request_id, trace_id, etc. - if strings.Contains(output, "request_id=") { - t.Errorf("expected no request_id, got: %s", output) - } - if strings.Contains(output, "trace_id=") { - t.Errorf("expected no trace_id, got: %s", output) - } -} - -// TestFormatValue tests the formatValue helper function -func TestFormatValue(t *testing.T) { - tests := []struct { - name string - input interface{} - expected string - }{ - {"simple string", "hello", "hello"}, - {"string with spaces", "hello world", `"hello world"`}, - {"string with quotes", `say "hello"`, `"say \"hello\""`}, - {"number", 42, "42"}, - {"boolean", true, "true"}, - {"nil", nil, "null"}, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - result := formatValue(tt.input) - if result != tt.expected { - t.Errorf("formatValue(%v) = %s, expected %s", tt.input, result, tt.expected) - } - }) - } -} diff --git a/pkg/metrics/reconciliation.go b/pkg/metrics/reconciliation.go index 94106f82..50e5d253 100644 --- a/pkg/metrics/reconciliation.go +++ b/pkg/metrics/reconciliation.go @@ -20,13 +20,13 @@ import ( "context" "database/sql" "fmt" + "log/slog" "sync" "time" "github.com/prometheus/client_golang/prometheus" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) const metricsSubsystem = "hyperfleet_api" @@ -158,7 +158,7 @@ func (c *ReconciliationCollector) Collect(ch chan<- prometheus.Metric) { rows, err := c.db.QueryContext(ctx, reconciliationQuery, threshold) //nolint:gosec // compile-time SQL if err != nil { - logger.WithError(ctx, err).Error("Failed to query reconciliation metrics") + slog.ErrorContext(ctx, "Failed to query reconciliation metrics", "error", err) c.emitInvalid(ch, err) return } @@ -170,7 +170,7 @@ func (c *ReconciliationCollector) Collect(ch chan<- prometheus.Metric) { var maxDuration float64 if err := rows.Scan(&resourceType, &isDelete, &pending, &stuck, &maxDuration); err != nil { - logger.WithError(ctx, err).Error("Failed to scan reconciliation metric row") + slog.ErrorContext(ctx, "Failed to scan reconciliation metric row", "error", err) c.emitInvalid(ch, err) return } @@ -182,7 +182,7 @@ func (c *ReconciliationCollector) Collect(ch chan<- prometheus.Metric) { } if err := rows.Err(); err != nil { - logger.WithError(ctx, err).Error("Error iterating reconciliation metric rows") + slog.ErrorContext(ctx, "Error iterating reconciliation metric rows", "error", err) c.emitInvalid(ch, err) } } diff --git a/pkg/middleware/masking.go b/pkg/middleware/masking.go index 2b688725..657ad8f5 100644 --- a/pkg/middleware/masking.go +++ b/pkg/middleware/masking.go @@ -3,12 +3,12 @@ package middleware import ( "context" "encoding/json" + "log/slog" "net/http" "regexp" "strings" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/config" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) const ( @@ -99,7 +99,7 @@ func (m *MaskingMiddleware) MaskHeaders(headers http.Header) http.Header { // Handles both top-level objects and top-level arrays // If masking is disabled, returns original body unchanged // If masking is enabled but JSON parsing fails, applies text-based fallback masking -func (m *MaskingMiddleware) MaskBody(body []byte) []byte { +func (m *MaskingMiddleware) MaskBody(ctx context.Context, body []byte) []byte { if len(body) == 0 { return body } @@ -110,15 +110,14 @@ func (m *MaskingMiddleware) MaskBody(body []byte) []byte { } if len(body) > maxBodySize { - logger.With(context.Background()).Warn("Body too large for JSON masking, using text fallback") + slog.WarnContext(ctx, "Body too large for JSON masking, using text fallback") return m.maskTextFallback(body) } var data interface{} if err := json.Unmarshal(body, &data); err != nil { // JSON parsing failed - use text-based fallback masking to prevent leakage - logger.WithError(context.Background(), err). - Warn("JSON parsing failed in MaskBody, applying text-based fallback masking") + slog.WarnContext(ctx, "JSON parsing failed in MaskBody, applying text-based fallback masking", "error", err) return m.maskTextFallback(body) } @@ -127,8 +126,7 @@ func (m *MaskingMiddleware) MaskBody(body []byte) []byte { masked, err := json.Marshal(data) if err != nil { // JSON marshaling failed - use text-based fallback masking to prevent leakage - logger.WithError(context.Background(), err). - Warn("JSON marshaling failed in MaskBody, applying text-based fallback masking") + slog.WarnContext(ctx, "JSON marshaling failed in MaskBody, applying text-based fallback masking", "error", err) return m.maskTextFallback(body) } return masked diff --git a/pkg/middleware/masking_test.go b/pkg/middleware/masking_test.go index c089c9ea..96b2aaf0 100644 --- a/pkg/middleware/masking_test.go +++ b/pkg/middleware/masking_test.go @@ -1,6 +1,7 @@ package middleware import ( + "context" "encoding/json" "fmt" "net/http" @@ -244,7 +245,7 @@ func TestMaskBody(t *testing.T) { }, } m := NewMaskingMiddleware(cfg) - result := m.MaskBody([]byte(tt.body)) + result := m.MaskBody(context.Background(), []byte(tt.body)) // For JSON objects, compare as maps to handle key ordering switch { diff --git a/pkg/middleware/otel.go b/pkg/middleware/otel.go index 52f76308..fa8be98a 100644 --- a/pkg/middleware/otel.go +++ b/pkg/middleware/otel.go @@ -7,7 +7,7 @@ import ( "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" "go.opentelemetry.io/otel/trace" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" ) // OTelMiddleware extracts W3C trace context and enriches logger context @@ -27,8 +27,8 @@ func OTelMiddleware(handler http.Handler) http.Handler { if span.SpanContext().IsValid() { traceID := span.SpanContext().TraceID().String() spanID := span.SpanContext().SpanID().String() - ctx = logger.WithTraceID(ctx, traceID) - ctx = logger.WithSpanID(ctx, spanID) + ctx = hfl.WithTraceID(ctx, traceID) + ctx = hfl.WithSpanID(ctx, spanID) } r = r.WithContext(ctx) diff --git a/pkg/middleware/otel_test.go b/pkg/middleware/otel_test.go index 28b664e5..985ed076 100644 --- a/pkg/middleware/otel_test.go +++ b/pkg/middleware/otel_test.go @@ -3,6 +3,7 @@ package middleware import ( "context" "fmt" + "log/slog" "net/http" "net/http/httptest" "testing" @@ -12,6 +13,7 @@ import ( "go.opentelemetry.io/otel/sdk/trace/tracetest" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" ) // setupTestTracer creates an in-memory tracer for testing @@ -24,18 +26,19 @@ func setupTestTracer() (*trace.TracerProvider, *tracetest.InMemoryExporter) { return tp, exporter } +func initTestLogger(t *testing.T) { + previous := slog.Default() + t.Cleanup(func() { slog.SetDefault(previous) }) + slog.SetDefault(logger.NewLogger("test", logger.HandlerConfig{ + Level: slog.LevelDebug, Format: hfl.FormatJSON, Output: httptest.NewRecorder(), Hostname: "test", + })) +} + // TestOTelMiddleware_SpanNameUsesRouteTemplate tests that span names use route templates // to prevent cardinality explosion (H3 security fix) func TestOTelMiddleware_SpanNameUsesRouteTemplate(t *testing.T) { // Initialize logger for testing - logger.InitGlobalLogger(&logger.LogConfig{ - Level: 0, // Debug - Format: logger.FormatJSON, - Output: httptest.NewRecorder(), - Component: "test", - Version: "test", - Hostname: "test", - }) + initTestLogger(t) tp, exporter := setupTestTracer() defer func() { @@ -125,14 +128,7 @@ func TestOTelMiddleware_SpanNameUsesRouteTemplate(t *testing.T) { // TestOTelMiddleware_TraceContextExtraction tests W3C trace context extraction func TestOTelMiddleware_TraceContextExtraction(t *testing.T) { - logger.InitGlobalLogger(&logger.LogConfig{ - Level: 0, - Format: logger.FormatJSON, - Output: httptest.NewRecorder(), - Component: "test", - Version: "test", - Hostname: "test", - }) + initTestLogger(t) tp, exporter := setupTestTracer() defer func() { @@ -177,10 +173,10 @@ func TestOTelMiddleware_TraceContextExtraction(t *testing.T) { testHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { ctx := r.Context() // Extract trace IDs from logger context - if traceID, ok := logger.GetTraceID(ctx); ok { + if traceID, ok := hfl.TraceIDFromContext(ctx); ok { capturedTraceID = traceID } - if spanID, ok := logger.GetSpanID(ctx); ok { + if spanID, ok := hfl.SpanIDFromContext(ctx); ok { capturedSpanID = spanID } w.WriteHeader(http.StatusOK) @@ -219,14 +215,7 @@ func TestOTelMiddleware_TraceContextExtraction(t *testing.T) { // TestOTelMiddleware_NoTraceContext tests middleware behavior without trace context func TestOTelMiddleware_NoTraceContext(t *testing.T) { - logger.InitGlobalLogger(&logger.LogConfig{ - Level: 0, - Format: logger.FormatJSON, - Output: httptest.NewRecorder(), - Component: "test", - Version: "test", - Hostname: "test", - }) + initTestLogger(t) tp, exporter := setupTestTracer() defer func() { @@ -265,14 +254,7 @@ func TestOTelMiddleware_NoTraceContext(t *testing.T) { // TestOTelMiddleware_CardinalityPrevention demonstrates cardinality fix func TestOTelMiddleware_CardinalityPrevention(t *testing.T) { - logger.InitGlobalLogger(&logger.LogConfig{ - Level: 0, - Format: logger.FormatJSON, - Output: httptest.NewRecorder(), - Component: "test", - Version: "test", - Hostname: "test", - }) + initTestLogger(t) tp, exporter := setupTestTracer() defer func() { diff --git a/pkg/middleware/schema_validation.go b/pkg/middleware/schema_validation.go index 965ba092..93aa1bf3 100644 --- a/pkg/middleware/schema_validation.go +++ b/pkg/middleware/schema_validation.go @@ -5,6 +5,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "regexp" @@ -22,19 +23,17 @@ func handleValidationError(w http.ResponseWriter, r *http.Request, err *errors.S } // Log validation errors as warn (client error, not server error) - logger.With(r.Context(), - "trace_id", traceID, - ).WithError(err).Warn("Validation error") + slog.WarnContext(r.Context(), + "Validation error", "trace_id", traceID, "error", err) // Write RFC 9457 Problem Details error response w.Header().Set("Content-Type", "application/problem+json") w.WriteHeader(err.HTTPCode) if encodeErr := json.NewEncoder(w).Encode(err.AsProblemDetails(r.URL.Path, traceID)); encodeErr != nil { - logger.With(r.Context(), - logger.HTTPPath(r.URL.Path), + slog.ErrorContext(r.Context(), + "Failed to encode validation error response", logger.HTTPPath(r.URL.Path), logger.HTTPMethod(r.Method), - logger.HTTPStatusCode(err.HTTPCode), - ).WithError(encodeErr).Error("Failed to encode validation error response") + logger.HTTPStatusCode(err.HTTPCode), "error", encodeErr) } } @@ -88,7 +87,7 @@ func SchemaValidationMiddleware(validator *validators.SchemaValidator) func(http return } if closeErr := r.Body.Close(); closeErr != nil { - logger.WithError(r.Context(), closeErr).Warn("Failed to close request body") + slog.WarnContext(r.Context(), "Failed to close request body", "error", closeErr) } // Restore the request body for the next handler diff --git a/pkg/services/adapter_status_validation.go b/pkg/services/adapter_status_validation.go index 9af1ec97..02d05e85 100644 --- a/pkg/services/adapter_status_validation.go +++ b/pkg/services/adapter_status_validation.go @@ -1,11 +1,12 @@ package services import ( + "context" "encoding/json" + "log/slog" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // validateAndClassifyAdapterStatus performs all stateless validation and discard-rule @@ -13,34 +14,35 @@ import ( // aggregation should be triggered. Returns (nil, false, nil) when the update should // be silently discarded. // -// This is the shared implementation used by ResourceService. Callers provide -// the resource generation and a pre-built logger with entity-specific context fields. +// This is the shared implementation used by ResourceService. The context retains +// request correlation and adapter identity supplied by the HTTP status handler, +// with resource context added by the service. func validateAndClassifyAdapterStatus( resourceGeneration int32, adapterStatus *api.AdapterStatus, existingStatus *api.AdapterStatus, - log *logger.ContextLogger, + ctx context.Context, ) ([]api.AdapterCondition, bool, *errors.ServiceError) { if adapterStatus.ObservedGeneration > resourceGeneration { - log.Debug("Discarding adapter status update: future generation") + slog.DebugContext(ctx, "Discarding adapter status update: future generation") return nil, false, nil } if existingStatus != nil && adapterStatus.ObservedGeneration < existingStatus.ObservedGeneration { - log.Debug("Discarding adapter status update: stale generation") + slog.DebugContext(ctx, "Discarding adapter status update: stale generation") return nil, false, nil } incomingObs := AdapterObservedTime(adapterStatus) if incomingObs.IsZero() { - log.Debug("Discarding adapter status update: zero observed time") + slog.DebugContext(ctx, "Discarding adapter status update: zero observed time") return nil, false, nil } if existingStatus != nil && adapterStatus.ObservedGeneration == existingStatus.ObservedGeneration { prevObs := AdapterObservedTime(existingStatus) if !prevObs.IsZero() && incomingObs.Before(prevObs) { - log.Debug("Discarding adapter status update: stale observed time") + slog.DebugContext(ctx, "Discarding adapter status update: stale observed time") return nil, false, nil } } @@ -79,7 +81,7 @@ func validateAndClassifyAdapterStatus( if cond.Status != api.AdapterConditionTrue && cond.Status != api.AdapterConditionFalse { if existingStatus != nil { - log.Debug("Discarding adapter status update: subsequent Unknown Available") + slog.DebugContext(ctx, "Discarding adapter status update: subsequent Unknown Available") return nil, false, nil } triggerAggregation = false diff --git a/pkg/services/adapter_status_validation_test.go b/pkg/services/adapter_status_validation_test.go index 68230f1c..c386d387 100644 --- a/pkg/services/adapter_status_validation_test.go +++ b/pkg/services/adapter_status_validation_test.go @@ -10,7 +10,6 @@ import ( "gorm.io/datatypes" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) func testConditionsJSON(conditions ...api.AdapterCondition) datatypes.JSON { @@ -35,15 +34,11 @@ func adapterStatusWithGenAndTime(gen int32, observedTime time.Time) *api.Adapter } } -func testLog() *logger.ContextLogger { - return logger.With(context.Background(), "test", "true") -} - func TestValidateAndClassify_FutureGeneration_Discards(t *testing.T) { RegisterTestingT(t) status := adapterStatusWithGenAndTime(5, time.Now()) - conditions, trigger, err := validateAndClassifyAdapterStatus(3, status, nil, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(3, status, nil, context.Background()) Expect(err).To(BeNil()) Expect(conditions).To(BeNil()) @@ -55,7 +50,7 @@ func TestValidateAndClassify_StaleGeneration_Discards(t *testing.T) { existing := &api.AdapterStatus{ObservedGeneration: 3} status := adapterStatusWithGenAndTime(2, time.Now()) - conditions, trigger, err := validateAndClassifyAdapterStatus(5, status, existing, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(5, status, existing, context.Background()) Expect(err).To(BeNil()) Expect(conditions).To(BeNil()) @@ -70,7 +65,7 @@ func TestValidateAndClassify_ZeroObservedTime_Discards(t *testing.T) { ObservedGeneration: 1, Conditions: testConditionsJSON(testMandatoryConditions(api.AdapterConditionTrue)...), } - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).To(BeNil()) Expect(conditions).To(BeNil()) @@ -84,7 +79,7 @@ func TestValidateAndClassify_StaleObservedTime_Discards(t *testing.T) { existing := adapterStatusWithGenAndTime(1, now) status := adapterStatusWithGenAndTime(1, now.Add(-time.Minute)) - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, existing, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, existing, context.Background()) Expect(err).To(BeNil()) Expect(conditions).To(BeNil()) @@ -99,7 +94,7 @@ func TestValidateAndClassify_MissingMandatoryCondition_ReturnsError(t *testing.T api.AdapterCondition{Type: api.AdapterConditionTypeAvailable, Status: api.AdapterConditionTrue}, ) - _, _, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + _, _, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).ToNot(BeNil()) Expect(err.Error()).To(ContainSubstring("mandatory condition")) @@ -115,7 +110,7 @@ func TestValidateAndClassify_InvalidAvailableStatus_ReturnsError(t *testing.T) { api.AdapterCondition{Type: api.AdapterConditionTypeHealth, Status: api.AdapterConditionTrue}, ) - _, _, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + _, _, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).ToNot(BeNil()) Expect(err.Error()).To(ContainSubstring("invalid status")) @@ -127,7 +122,7 @@ func TestValidateAndClassify_FirstUnknownAvailable_Accepted(t *testing.T) { status := adapterStatusWithGenAndTime(1, time.Now()) status.Conditions = testConditionsJSON(testMandatoryConditions(api.AdapterConditionUnknown)...) - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).To(BeNil()) Expect(conditions).ToNot(BeNil()) @@ -141,7 +136,7 @@ func TestValidateAndClassify_SubsequentUnknownAvailable_Discards(t *testing.T) { status := adapterStatusWithGenAndTime(1, time.Now()) status.Conditions = testConditionsJSON(testMandatoryConditions(api.AdapterConditionUnknown)...) - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, existing, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, existing, context.Background()) Expect(err).To(BeNil()) Expect(conditions).To(BeNil()) @@ -153,7 +148,7 @@ func TestValidateAndClassify_AvailableTrue_TriggersAggregation(t *testing.T) { status := adapterStatusWithGenAndTime(1, time.Now()) - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).To(BeNil()) Expect(conditions).ToNot(BeNil()) @@ -166,7 +161,7 @@ func TestValidateAndClassify_AvailableFalse_TriggersAggregation(t *testing.T) { status := adapterStatusWithGenAndTime(1, time.Now()) status.Conditions = testConditionsJSON(testMandatoryConditions(api.AdapterConditionFalse)...) - conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, testLog()) + conditions, trigger, err := validateAndClassifyAdapterStatus(1, status, nil, context.Background()) Expect(err).To(BeNil()) Expect(conditions).ToNot(BeNil()) diff --git a/pkg/services/aggregation.go b/pkg/services/aggregation.go index 392ca066..23638970 100644 --- a/pkg/services/aggregation.go +++ b/pkg/services/aggregation.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "sort" "strings" "time" @@ -122,7 +123,8 @@ func parsePrevConditions(ctx context.Context, raw []byte) ( } var conditions []api.ResourceCondition if err := json.Unmarshal(raw, &conditions); err != nil { - logger.WithError(ctx, err).Error("Failed to unmarshal previous conditions JSON; proceeding with empty state") + slog.ErrorContext(ctx, "Failed to unmarshal previous conditions JSON; proceeding with empty state", + "error", err) return nil, nil, prevAdapterByType } for i := range conditions { @@ -176,8 +178,9 @@ func normalizeAdapterReportsForAggregation( var conditions []api.AdapterCondition if len(as.Conditions) > 0 { if err := json.Unmarshal(as.Conditions, &conditions); err != nil { - logger.With(ctx, "adapter", as.Adapter).WithError(err). - Error("Failed to unmarshal adapter status conditions; skipping adapter") + slog.ErrorContext(logger.WithAdapter(ctx, as.Adapter), + "Failed to unmarshal adapter status conditions; skipping adapter", "error", err, + ) continue } } diff --git a/pkg/services/condition_mapper.go b/pkg/services/condition_mapper.go index 6cc43f5b..acbace27 100644 --- a/pkg/services/condition_mapper.go +++ b/pkg/services/condition_mapper.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "math" "sort" "strings" @@ -223,8 +224,10 @@ func (m *ConditionMapper) evaluateRule( // Skip condition if reason exceeds max length (per JIRA AC: "skip condition") if len(reasonStr) > registry.MaxConditionReasonLength { - logger.With(ctx, "resource_kind", m.resourceKind, "condition_type", rule.conditionType). - Warn("Condition skipped: reason exceeds max length") + slog.WarnContext(ctx, + "Condition skipped: reason exceeds max length", + "resource_kind", m.resourceKind, "condition_type", rule.conditionType, + ) return nil, nil } @@ -245,8 +248,9 @@ func (m *ConditionMapper) truncateMessage( ) string { if len(messageStr) > registry.MaxConditionMessageLength { truncated := truncateUTF8(messageStr, registry.MaxConditionMessageLength) - logger.With(ctx, "resource_kind", m.resourceKind, "condition_type", rule.conditionType). - Info("Condition message truncated to max length") + slog.InfoContext(ctx, + "Condition message truncated to max length", "resource_kind", m.resourceKind, "condition_type", rule.conditionType, + ) return truncated } return messageStr @@ -321,8 +325,10 @@ func extractResourceGeneration( return 0 } if gen < math.MinInt32 || gen > math.MaxInt32 { - logger.With(ctx, "resource_kind", resourceKind, "condition_type", conditionType, "generation", gen). - Warn("Resource generation out of int32 range, using 0") + slog.WarnContext(ctx, + "Resource generation out of int32 range, "+ + "using 0", "resource_kind", resourceKind, "condition_type", conditionType, "generation", gen, + ) return 0 } return int32(gen) @@ -480,7 +486,6 @@ func buildStatusesList(ctx context.Context, statuses api.AdapterStatusList) []in func parseConditionsWithUnknownCheck( ctx context.Context, conditionsJSON []byte, - adapterName string, ) ([]map[string]interface{}, bool) { // Initialize to empty slice (not nil) so CEL receives [] instead of null conditions := make([]map[string]interface{}, 0) @@ -495,9 +500,9 @@ func parseConditionsWithUnknownCheck( // Unmarshal failure: return empty conditions array. // Degraded mode: statuses array contains entry with empty conditions, allowing // resource-level CEL expressions to still run (e.g., counting adapters). - logger.With(ctx, "adapter", adapterName). - WithError(err). - Warn("Failed to unmarshal adapter conditions JSONB, using empty conditions array") + slog.WarnContext(ctx, + "Failed to unmarshal adapter conditions JSONB, using empty conditions array", "error", err, + ) return conditions, hasUnknown } @@ -537,7 +542,7 @@ func parseConditionsWithUnknownCheck( // parseAdapterData unmarshals adapter data from JSONB to a map. // Returns empty map on unmarshal failure to maintain CEL context consistency. -func parseAdapterData(ctx context.Context, dataJSON []byte, adapterName string) map[string]interface{} { +func parseAdapterData(ctx context.Context, dataJSON []byte) map[string]interface{} { data := make(map[string]interface{}) if dataJSON == nil { @@ -546,9 +551,9 @@ func parseAdapterData(ctx context.Context, dataJSON []byte, adapterName string) if err := json.Unmarshal(dataJSON, &data); err != nil { // Reset to empty map on parse failure to maintain consistency - logger.With(ctx, "adapter", adapterName). - WithError(err). - Warn("Failed to unmarshal adapter data JSONB, using empty map") + slog.WarnContext(ctx, + "Failed to unmarshal adapter data JSONB, using empty map", "error", err, + ) return make(map[string]interface{}) } @@ -570,7 +575,8 @@ func adapterStatusToMapWithUnknownCheck(ctx context.Context, status *api.Adapter } // Parse conditions and check for Unknown status - conditions, hasUnknown := parseConditionsWithUnknownCheck(ctx, status.Conditions, status.Adapter) + ctx = logger.WithAdapter(ctx, status.Adapter) + conditions, hasUnknown := parseConditionsWithUnknownCheck(ctx, status.Conditions) // Early return if Unknown found - buildStatusesList discards the map anyway // Return nil instead of allocating a throwaway map (saves allocation on hot path) @@ -579,7 +585,7 @@ func adapterStatusToMapWithUnknownCheck(ctx context.Context, status *api.Adapter } // Parse data field from JSONB - data := parseAdapterData(ctx, status.Data, status.Adapter) + data := parseAdapterData(ctx, status.Data) statusMap := map[string]interface{}{ celKeyAdapter: status.Adapter, @@ -602,8 +608,9 @@ func resourceToMap(ctx context.Context, resource interface{}, resourceKind strin if err != nil { // Marshal failure: return empty map. // Degraded mode: CEL expressions using resource.* will receive empty object. - logger.With(ctx, "resource_kind", resourceKind).WithError(err). - Warn("Failed to marshal resource to JSON, using empty map") + slog.WarnContext(ctx, + "Failed to marshal resource to JSON, using empty map", "resource_kind", resourceKind, "error", err, + ) return make(map[string]interface{}) } @@ -611,8 +618,9 @@ func resourceToMap(ctx context.Context, resource interface{}, resourceKind strin if err := json.Unmarshal(data, &result); err != nil { // Unmarshal failure: return empty map. // Degraded mode: CEL expressions using resource.* will receive empty object. - logger.With(ctx, "resource_kind", resourceKind).WithError(err). - Warn("Failed to unmarshal resource JSON to map, using empty map") + slog.WarnContext(ctx, + "Failed to unmarshal resource JSON to map, using empty map", "resource_kind", resourceKind, "error", err, + ) return make(map[string]interface{}) } diff --git a/pkg/services/resource.go b/pkg/services/resource.go index e8bba99a..e6f2694b 100644 --- a/pkg/services/resource.go +++ b/pkg/services/resource.go @@ -4,9 +4,11 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "strings" "time" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/trace" @@ -14,7 +16,6 @@ import ( "github.com/openshift-hyperfleet/hyperfleet-api/pkg/dao" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/metrics" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/registry" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/tenant" @@ -609,6 +610,8 @@ func (s *sqlResourceService) ListAll( func (s *sqlResourceService) ProcessAdapterStatus( ctx context.Context, kind, resourceID string, adapterStatus *api.AdapterStatus, ) (*api.AdapterStatus, *errors.ServiceError) { + ctx = hfl.WithResourceType(ctx, kind) + ctx = hfl.WithResourceID(ctx, resourceID) trace.SpanFromContext(ctx).SetAttributes(attribute.String("hyperfleet.resource_id", resourceID)) if svcErr := validateKind(kind); svcErr != nil { return nil, svcErr @@ -629,10 +632,8 @@ func (s *sqlResourceService) ProcessAdapterStatus( } existingStatus := findAdapterStatusInList(allStatuses, adapterStatus.Adapter) - log := logger.With(ctx, "resource_type", kind, "resource_id", resourceID, - logger.FieldAdapter, adapterStatus.Adapter) conditions, triggerAggregation, svcErr := validateAndClassifyAdapterStatus( - resource.Generation, adapterStatus, existingStatus, log, + resource.Generation, adapterStatus, existingStatus, ctx, ) if svcErr != nil { return svcErr @@ -800,6 +801,8 @@ func (s *sqlResourceService) tryHardDeleteResource( conditions []api.AdapterCondition, allStatuses api.AdapterStatusList, ) (bool, *errors.ServiceError) { + resourceCtx := hfl.WithResourceType(ctx, resource.Kind) + resourceCtx = hfl.WithResourceID(resourceCtx, resource.ID) // Quick check: does the incoming report contain Finalized=True? // If not, hard-delete is not possible regardless of other adapters. if !incomingReportedFinalized(conditions) { @@ -841,18 +844,16 @@ func (s *sqlResourceService) tryHardDeleteResource( // All checks passed — clean up associated data and hard-delete the resource. // Order matters: adapter statuses and conditions must be removed before the // resource row, since they reference it. - if err := s.adapterStatusDao.DeleteByResource(ctx, resource.Kind, resource.ID); err != nil { + if err := s.adapterStatusDao.DeleteByResource(resourceCtx, resource.Kind, resource.ID); err != nil { return false, errors.GeneralError("Failed to delete adapter statuses during hard-delete: %s", err) } - if err := s.resourceConditionDao.DeleteByResource(ctx, resource.ID); err != nil { + if err := s.resourceConditionDao.DeleteByResource(resourceCtx, resource.ID); err != nil { return false, errors.GeneralError("Failed to delete resource conditions during hard-delete: %s", err) } - if err := s.resourceDao.Delete(ctx, resource.Kind, resource.ID); err != nil { + if err := s.resourceDao.Delete(resourceCtx, resource.Kind, resource.ID); err != nil { return false, errors.GeneralError("Failed to hard-delete %s: %s", resource.Kind, err) } - - logger.With(ctx, "resource_type", resource.Kind, "resource_id", resource.ID). - Info("Hard-deleted resource after all required adapters reported Finalized=True") + slog.InfoContext(resourceCtx, "Hard-deleted resource after all required adapters reported Finalized=True") return true, nil } @@ -1008,14 +1009,15 @@ func (s *sqlResourceService) ForceDelete(ctx context.Context, kind, id, reason s func (s *sqlResourceService) forceDeleteResourceTree( ctx context.Context, resource *api.Resource, caller, reason string, ) *errors.ServiceError { + resourceCtx := hfl.WithResourceType(ctx, resource.Kind) + resourceCtx = hfl.WithResourceID(resourceCtx, resource.ID) children := registry.ChildrenOf(resource.Kind) childIDs := make([]string, 0) for _, child := range children { - items, err := s.resourceDao.FindByKindAndOwnerForUpdate(ctx, child.Kind, resource.ID) + items, err := s.resourceDao.FindByKindAndOwnerForUpdate(resourceCtx, child.Kind, resource.ID) if err != nil { - logger.With(ctx, "resource_id", resource.ID, "child_kind", child.Kind). - WithError(err).Error("Failed to find children for force-delete") + slog.ErrorContext(resourceCtx, "Failed to find children for force-delete", "child_kind", child.Kind, "error", err) return errors.GeneralError("Unable to find %s children for force-delete", child.Kind) } for _, item := range items { @@ -1025,32 +1027,27 @@ func (s *sqlResourceService) forceDeleteResourceTree( } } } - - logger.With(ctx, - "resource_kind", resource.Kind, - "resource_id", resource.ID, + slog.InfoContext(resourceCtx, + "Force-deleting resource", "caller", caller, "reason", reason, "child_resource_ids", childIDs, - ).Info("Force-deleting resource") + ) - if err := s.adapterStatusDao.DeleteByResource(ctx, resource.Kind, resource.ID); err != nil { + if err := s.adapterStatusDao.DeleteByResource(resourceCtx, resource.Kind, resource.ID); err != nil { return errors.GeneralError("Failed to delete adapter statuses during force-delete: %s", err) } - if err := s.resourceConditionDao.DeleteByResource(ctx, resource.ID); err != nil { + if err := s.resourceConditionDao.DeleteByResource(resourceCtx, resource.ID); err != nil { return errors.GeneralError("Failed to delete resource conditions during force-delete: %s", err) } // Clear inbound references before hard-deleting (FK uses ON DELETE RESTRICT). // Note: referencing resources with Min>0 on this ref type will silently // violate their required-reference invariant after this operation. - if err := s.resourceDao.ClearTargetReferences(ctx, resource.ID); err != nil { + if err := s.resourceDao.ClearTargetReferences(resourceCtx, resource.ID); err != nil { return errors.GeneralError("failed to clear references: %s", err) } - logger.With(ctx, - "resource_kind", resource.Kind, - "resource_id", resource.ID, - ).Info("Cleared inbound references for force-delete") - if err := s.resourceDao.Delete(ctx, resource.Kind, resource.ID); err != nil { + slog.InfoContext(resourceCtx, "Cleared inbound references for force-delete") + if err := s.resourceDao.Delete(resourceCtx, resource.Kind, resource.ID); err != nil { return handleDeleteError(resource.Kind, err) } diff --git a/pkg/services/resource_logging_test.go b/pkg/services/resource_logging_test.go new file mode 100644 index 00000000..2b5c50c9 --- /dev/null +++ b/pkg/services/resource_logging_test.go @@ -0,0 +1,121 @@ +package services + +import ( + "bytes" + "encoding/json" + "fmt" + "log/slog" + "sync" + "testing" + "time" + + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" + + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" + "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" +) + +func captureServiceLogs(t *testing.T, level slog.Level) *bytes.Buffer { + t.Helper() + var output bytes.Buffer + previous := slog.Default() + slog.SetDefault(logger.NewLogger("test", logger.HandlerConfig{ + Level: level, Format: hfl.FormatJSON, Output: &output, + })) + t.Cleanup(func() { slog.SetDefault(previous) }) + return &output +} + +func TestProcessAdapterStatus_ConcurrentReportsRetainLogCorrelation(t *testing.T) { + setupAdapterStatusDescriptors() + mockDao := newMockResourceDao() + svc, _, _, _ := newTestResourceServiceWithAdapterStatus(mockDao) + resource := testResource("TestResource", "r-1", "test") + resource.Generation = 1 + mockDao.addResource(resource) + output := captureServiceLogs(t, slog.LevelDebug) + parent := hfl.WithTraceID(t.Context(), "trace-1") + parent = hfl.WithSpanID(parent, "span-1") + start := make(chan struct{}) + var wg sync.WaitGroup + for i := range 2 { + wg.Go(func() { + <-start + ctx := hfl.Set(parent, logger.ReqIDKey, fmt.Sprintf("request-%d", i)) + status := testAdapterStatusRequest(99) + status.Adapter = fmt.Sprintf("adapter-%d", i) + reportCtx := logger.WithAdapter(ctx, status.Adapter) + result, err := svc.ProcessAdapterStatus(reportCtx, resource.Kind, resource.ID, status) + if err != nil || result != nil { + t.Errorf("future report: result = %v, error = %v", result, err) + } + if _, ok := hfl.Get(ctx, logger.AdapterKey); ok { + t.Error("processing must not change the caller's adapter context") + } + }) + } + close(start) + wg.Wait() + + lines := bytes.Split(bytes.TrimSpace(output.Bytes()), []byte("\n")) + if len(lines) != 2 { + t.Fatalf("got %d log records, want 2: %s", len(lines), output.String()) + } + seen := make(map[string]bool) + for _, line := range lines { + var record map[string]any + if err := json.Unmarshal(line, &record); err != nil { + t.Fatal(err) + } + requestID, ok := record["request_id"].(string) + if !ok { + t.Fatalf("request_id missing: %s", line) + } + seen[requestID] = true + wantAdapter := map[string]string{"request-0": "adapter-0", "request-1": "adapter-1"}[requestID] + for key, want := range map[string]string{ + "adapter": wantAdapter, "resource_type": resource.Kind, "resource_id": resource.ID, + "trace_id": "trace-1", "span_id": "span-1", + "message": "Discarding adapter status update: future generation", + } { + if record[key] != want { + t.Errorf("%s = %v, want %q", key, record[key], want) + } + } + } + if !seen["request-0"] || !seen["request-1"] { + t.Errorf("missing report logs: %v", seen) + } +} + +func TestAdapterDiagnostics_IdentifyAdapterAndClassifyStacks(t *testing.T) { + output := captureServiceLogs(t, slog.LevelInfo) + ctx := logger.WithAdapter(t.Context(), "reporting-adapter") + parsePrevConditions(ctx, []byte("invalid JSON")) + normalizeAdapterReportsForAggregation(ctx, api.AdapterStatusList{ + makeAdapterStatus("other-adapter", time.Now(), 1, []byte("invalid JSON")), + }, []string{"other-adapter"}, 1) + adapterStatusToMapWithUnknownCheck(ctx, &api.AdapterStatus{ + Adapter: "mapper-adapter", Conditions: []byte("invalid JSON"), Data: []byte("invalid JSON"), + }) + + lines := bytes.Split(bytes.TrimSpace(output.Bytes()), []byte("\n")) + if len(lines) != 4 { + t.Fatalf("got %d records, want 4: %s", len(lines), output.String()) + } + for i, line := range lines { + var record map[string]any + if err := json.Unmarshal(line, &record); err != nil { + t.Fatal(err) + } + if _, hasStack := record["stack_trace"]; hasStack != (i < 2) { + t.Errorf("only ERROR diagnostics must include a stack: %s", line) + } + wantAdapter := []string{ + "reporting-adapter", "other-adapter", "mapper-adapter", "mapper-adapter", + }[i] + if record["adapter"] != wantAdapter || bytes.Count(line, []byte(`"adapter":`)) != 1 { + t.Errorf("record must identify %q once: %s", wantAdapter, line) + } + } +} diff --git a/pkg/services/util.go b/pkg/services/util.go index 94c74455..f2766eef 100755 --- a/pkg/services/util.go +++ b/pkg/services/util.go @@ -14,7 +14,6 @@ import ( "github.com/openshift-hyperfleet/hyperfleet-api/pkg/auth" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/db" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) const defaultSystemUser = "system@hyperfleet.local" @@ -81,31 +80,6 @@ func handleDeleteError(resourceType string, err error) *errors.ServiceError { return errors.GeneralError("Unable to delete %s: %s", resourceType, err.Error()) } -type adapterSummary struct { - Conditions map[string]string `json:"conditions"` - Adapter string `json:"adapter"` -} - -func buildAdapterSummaries(ctx context.Context, statuses api.AdapterStatusList) []adapterSummary { - summaries := make([]adapterSummary, 0, len(statuses)) - for _, st := range statuses { - conds := make(map[string]string) - if len(st.Conditions) > 0 { - var parsed []api.AdapterCondition - if err := json.Unmarshal(st.Conditions, &parsed); err != nil { - logger.With(ctx, "adapter", st.Adapter). - WithError(err).Warn("Failed to parse adapter conditions for summary") - } else { - for _, c := range parsed { - conds[c.Type] = string(c.Status) - } - } - } - summaries = append(summaries, adapterSummary{Adapter: st.Adapter, Conditions: conds}) - } - return summaries -} - func actorFromContext(ctx context.Context) string { if caller := auth.GetUsernameFromContext(ctx); caller != "" { return caller diff --git a/pkg/services/util_test.go b/pkg/services/util_test.go index 5f966073..55e472f6 100644 --- a/pkg/services/util_test.go +++ b/pkg/services/util_test.go @@ -1,13 +1,9 @@ package services import ( - "context" - "encoding/json" "testing" . "github.com/onsi/gomega" - - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/api" ) func TestJSONEqual(t *testing.T) { @@ -135,85 +131,3 @@ func TestJSONEqual(t *testing.T) { }) } } - -func TestBuildAdapterSummaries(t *testing.T) { - t.Parallel() - - tests := []struct { - name string - statuses api.AdapterStatusList - expected []adapterSummary - }{ - { - name: "empty input", - statuses: api.AdapterStatusList{}, - expected: []adapterSummary{}, - }, - { - name: "valid conditions", - statuses: api.AdapterStatusList{ - { - Adapter: "validation", - Conditions: mustMarshal([]api.AdapterCondition{ - {Type: "Applied", Status: "True"}, - {Type: "Available", Status: "False"}, - }), - }, - }, - expected: []adapterSummary{ - {Adapter: "validation", Conditions: map[string]string{"Applied": "True", "Available": "False"}}, - }, - }, - { - name: "empty conditions field", - statuses: api.AdapterStatusList{ - {Adapter: "provisioning", Conditions: nil}, - }, - expected: []adapterSummary{ - {Adapter: "provisioning", Conditions: map[string]string{}}, - }, - }, - { - name: "malformed JSON falls back to empty map", - statuses: api.AdapterStatusList{ - {Adapter: "broken", Conditions: []byte(`not valid json`)}, - }, - expected: []adapterSummary{ - {Adapter: "broken", Conditions: map[string]string{}}, - }, - }, - { - name: "multiple adapters", - statuses: api.AdapterStatusList{ - { - Adapter: "validation", - Conditions: mustMarshal([]api.AdapterCondition{{Type: "Applied", Status: "True"}}), - }, - { - Adapter: "provisioning", - Conditions: mustMarshal([]api.AdapterCondition{{Type: "Reconciled", Status: "False"}}), - }, - }, - expected: []adapterSummary{ - {Adapter: "validation", Conditions: map[string]string{"Applied": "True"}}, - {Adapter: "provisioning", Conditions: map[string]string{"Reconciled": "False"}}, - }, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - RegisterTestingT(t) - result := buildAdapterSummaries(context.Background(), tt.statuses) - Expect(result).To(Equal(tt.expected)) - }) - } -} - -func mustMarshal(v interface{}) []byte { - b, err := json.Marshal(v) - if err != nil { - panic(err) - } - return b -} diff --git a/pkg/telemetry/otel.go b/pkg/telemetry/otel.go index 536bb404..8165bda4 100644 --- a/pkg/telemetry/otel.go +++ b/pkg/telemetry/otel.go @@ -3,6 +3,7 @@ package telemetry import ( "context" "fmt" + "log/slog" "os" "strconv" "strings" @@ -58,12 +59,11 @@ func InitTraceProvider(ctx context.Context, serviceName, serviceVersion string) ) if err != nil { if shutdownErr := exporter.Shutdown(ctx); shutdownErr != nil { - logger.WithError(ctx, shutdownErr).Warn("Failed to shutdown exporter") + slog.WarnContext(ctx, "Failed to shutdown exporter", "error", shutdownErr) } - logger.With(ctx, - logger.FieldServiceName, serviceName, - logger.FieldServiceVersion, serviceVersion, - ).WithError(err).Error("Failed to create OpenTelemetry resource") + slog.ErrorContext(ctx, + "Failed to create OpenTelemetry resource", logger.FieldServiceName, serviceName, + logger.FieldServiceVersion, serviceVersion, "error", err) return nil, fmt.Errorf("failed to create OTel resource: %w", err) } @@ -94,7 +94,7 @@ func createExporter(ctx context.Context) (trace.SpanExporter, error) { // Create stdout exporter when no OTLP endpoint is configured exporter, err := stdouttrace.New() if err != nil { - logger.WithError(ctx, err).Error("Failed to create OpenTelemetry stdout exporter") + slog.ErrorContext(ctx, "Failed to create OpenTelemetry stdout exporter", "error", err) return nil, fmt.Errorf("failed to create OpenTelemetry stdout exporter: %w", err) } return exporter, nil @@ -107,23 +107,23 @@ func createExporter(ctx context.Context) (trace.SpanExporter, error) { // Note: http/json not yet supported - use http/protobuf exporter, err := otlptracehttp.New(ctx) if err != nil { - logger.With(ctx, logger.FieldProtocol, protocol).WithError(err).Error("Failed to create OTLP exporter") + slog.ErrorContext(ctx, "Failed to create OTLP exporter", logger.FieldProtocol, protocol, "error", err) return nil, fmt.Errorf("failed to create OTLP exporter (protocol=%s): %w", protocol, err) } return exporter, nil case "grpc", "": // Default to gRPC per standard exporter, err := otlptracegrpc.New(ctx) if err != nil { - logger.With(ctx, logger.FieldProtocol, protocol).WithError(err).Error("Failed to create OTLP exporter") + slog.ErrorContext(ctx, "Failed to create OTLP exporter", logger.FieldProtocol, protocol, "error", err) return nil, fmt.Errorf("failed to create OTLP exporter (protocol=%s): %w", protocol, err) } return exporter, nil default: // Spec-compliant values: grpc, http/protobuf - logger.With(ctx, logger.FieldProtocol, protocol).Warn("Unrecognized OTEL_EXPORTER_OTLP_PROTOCOL, using default grpc") + slog.WarnContext(ctx, "Unrecognized OTEL_EXPORTER_OTLP_PROTOCOL, using default grpc", logger.FieldProtocol, protocol) exporter, err := otlptracegrpc.New(ctx) if err != nil { - logger.With(ctx, logger.FieldProtocol, protocol).WithError(err).Error("Failed to create OTLP exporter") + slog.ErrorContext(ctx, "Failed to create OTLP exporter", logger.FieldProtocol, protocol, "error", err) return nil, fmt.Errorf("failed to create OTLP exporter (protocol=%s): %w", protocol, err) } return exporter, nil @@ -149,7 +149,7 @@ func selectSampler(ctx context.Context) trace.Sampler { case parentBasedAlwaysOff: return trace.ParentBased(trace.NeverSample()) default: - logger.With(ctx, logger.FieldSampler, samplerType).Warn("Unrecognized sampler, using default") + slog.WarnContext(ctx, "Unrecognized sampler, using default", logger.FieldSampler, samplerType) return trace.ParentBased(trace.TraceIDRatioBased(parseSamplingRate(ctx))) } } @@ -169,8 +169,9 @@ func parseSamplingRate(ctx context.Context) float64 { if parsedRate, err := strconv.ParseFloat(arg, 64); err == nil && parsedRate >= 0.0 && parsedRate <= 1.0 { rate = parsedRate } else { - logger.With(ctx, logger.FieldSamplingRate, rate, "raw_value", arg). - Warn("Invalid OTEL_TRACES_SAMPLER_ARG value, using default") + slog.WarnContext(ctx, + "Invalid OTEL_TRACES_SAMPLER_ARG value, using default", logger.FieldSamplingRate, rate, "raw_value", arg, + ) } } return rate diff --git a/pkg/tenant/middleware.go b/pkg/tenant/middleware.go index baa4ae63..5fe2e0f6 100644 --- a/pkg/tenant/middleware.go +++ b/pkg/tenant/middleware.go @@ -3,6 +3,7 @@ package tenant import ( "context" "fmt" + "log/slog" "net/http" "regexp" "strings" @@ -11,7 +12,6 @@ import ( "github.com/openshift-hyperfleet/hyperfleet-api/pkg/auth" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/config" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" ) // maxDimensionValueLen bounds tenant dimension header values to the RFC 1123 @@ -104,7 +104,7 @@ func handleForbidden( ctx context.Context, w http.ResponseWriter, r *http.Request, reason string, values ...interface{}, ) { err := errors.Forbidden(reason, values...) - logger.WithError(ctx, err).Warn("Tenant identity rejected") + slog.WarnContext(ctx, "Tenant identity rejected", "error", err) response.WriteServiceErrorResponse(ctx, w, r, err) } diff --git a/pkg/validators/schema_validator.go b/pkg/validators/schema_validator.go index 8a015eb6..6179bfe1 100644 --- a/pkg/validators/schema_validator.go +++ b/pkg/validators/schema_validator.go @@ -3,11 +3,11 @@ package validators import ( "context" "fmt" + "log/slog" "strings" "github.com/getkin/kin-openapi/openapi3" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/errors" - "github.com/openshift-hyperfleet/hyperfleet-api/pkg/logger" "github.com/openshift-hyperfleet/hyperfleet-api/pkg/registry" ) @@ -56,11 +56,11 @@ func buildSchemasMap(doc *openapi3.T) map[string]*ResourceSchema { for _, d := range registry.WithSpecSchema() { schemaRef := doc.Components.Schemas[d.SpecSchemaName] if schemaRef == nil { - logger.With(ctx, - "schema_name", d.SpecSchemaName, + slog.WarnContext(ctx, + "OpenAPI spec schema not found, skipping validation for entity", "schema_name", d.SpecSchemaName, "kind", d.Kind, "plural", d.Plural, - ).Warn("OpenAPI spec schema not found, skipping validation for entity") + ) continue } schemas[d.Plural] = &ResourceSchema{ diff --git a/test/helper.go b/test/helper.go index a6fd23de..640e0658 100755 --- a/test/helper.go +++ b/test/helper.go @@ -18,6 +18,7 @@ import ( "github.com/brianvoe/gofakeit/v7" "github.com/golang-jwt/jwt/v5" "github.com/google/uuid" + hfl "github.com/openshift-hyperfleet/hyperfleet-logger" "github.com/spf13/cobra" "gorm.io/gorm" @@ -208,7 +209,7 @@ func NewHelper() *Helper { } if logLevel := os.Getenv("LOGLEVEL"); logLevel != "" { - logger.With(ctx, logger.FieldLogLevel, logLevel).Info("Using custom loglevel") + slog.InfoContext(ctx, "Using custom loglevel", logger.FieldLogLevel, logLevel) cfg.Logging.Level = logLevel } @@ -255,7 +256,7 @@ func NewHelper() *Helper { func (helper *Helper) Teardown() { if err := helper.closer.Close(); err != nil { - logger.WithError(context.Background(), err).Error("teardown errors") + slog.ErrorContext(context.Background(), "teardown errors", "error", err) } } @@ -268,9 +269,9 @@ func (helper *Helper) requireJWTIssuers() { // abortSetup logs msg, cleans up already-created resources via c, then panics - for unrecoverable NewHelper failures. func abortSetup(ctx context.Context, c *closer.Closer, err error, msg string) { if err != nil { - logger.WithError(ctx, err).Error(msg) + slog.ErrorContext(ctx, msg, "error", err) } else { - logger.Error(ctx, msg) + slog.ErrorContext(ctx, msg) } _ = c.Close() panic(fmt.Sprintf("test setup: %s", msg)) @@ -308,11 +309,11 @@ func (helper *Helper) startAPIServer() { abortSetup(ctx, helper.closer, err, "Unable to start Test API server") } go func() { - logger.Debug(ctx, "Test API server started") + slog.DebugContext(ctx, "Test API server started") if err := helper.APIServer.Serve(listener); err != nil { - logger.WithError(ctx, err).Error("Test API server terminated with errors") + slog.ErrorContext(ctx, "Test API server terminated with errors", "error", err) } - logger.Debug(ctx, "Test API server stopped") + slog.DebugContext(ctx, "Test API server stopped") }() } @@ -695,13 +696,11 @@ RVJUSUZJQ0FURS0tLS0tCg==` } func initTestLogger() { - cfg := &logger.LogConfig{ - Level: slog.LevelInfo, - Format: logger.FormatText, - Output: os.Stdout, - Component: "hyperfleet-api-test", - Version: "test", - Hostname: "test-host", - } - logger.InitGlobalLogger(cfg) + level, err := hfl.ParseLevel(os.Getenv("LOGLEVEL")) + if err != nil { + level = slog.LevelInfo + } + slog.SetDefault(logger.NewLogger("test", logger.HandlerConfig{ + Level: level, Format: hfl.FormatText, Output: os.Stdout, Hostname: "test-host", + })) } diff --git a/test/helper_test.go b/test/helper_test.go new file mode 100644 index 00000000..4c4f1a83 --- /dev/null +++ b/test/helper_test.go @@ -0,0 +1,18 @@ +package test + +import ( + "log/slog" + "testing" +) + +func TestInitTestLoggerHonorsLogLevel(t *testing.T) { + previous := slog.Default() + t.Cleanup(func() { slog.SetDefault(previous) }) + t.Setenv("LOGLEVEL", "DEBUG") + + initTestLogger() + + if !slog.Default().Enabled(t.Context(), slog.LevelDebug) { + t.Fatal("debug logging should be enabled when LOGLEVEL=DEBUG") + } +} diff --git a/test/integration/integration_test.go b/test/integration/integration_test.go index 81b33856..60bf6038 100755 --- a/test/integration/integration_test.go +++ b/test/integration/integration_test.go @@ -3,6 +3,7 @@ package integration import ( "context" "flag" + "log/slog" "os" "path/filepath" "runtime" @@ -24,7 +25,7 @@ func TestMain(m *testing.M) { func runTestMain(m *testing.M) int { flag.Parse() ctx := context.Background() - logger.With(ctx, "go_version", runtime.Version()).Info("Starting integration test") + slog.InfoContext(ctx, "Starting integration test", "go_version", runtime.Version()) // Set OpenAPI schema path for integration tests if not already set // This enables schema validation middleware during tests @@ -32,7 +33,7 @@ func runTestMain(m *testing.M) int { if os.Getenv("HYPERFLEET_SERVER_OPENAPI_SCHEMA_PATH") == "" { _, filename, _, ok := runtime.Caller(0) if !ok { - logger.Warn(ctx, "Failed to determine current file path via runtime.Caller, skipping schema path setup") + slog.WarnContext(ctx, "Failed to determine current file path via runtime.Caller, skipping schema path setup") } else { integrationDir := filepath.Dir(filename) testDir := filepath.Dir(integrationDir) @@ -44,8 +45,9 @@ func runTestMain(m *testing.M) int { schemaPath = filepath.Join(repoRoot, "openapi", "openapi.yaml") } _ = os.Setenv("HYPERFLEET_SERVER_OPENAPI_SCHEMA_PATH", schemaPath) - logger.With(ctx, logger.FieldSchemaPath, schemaPath). - Info("Set HYPERFLEET_SERVER_OPENAPI_SCHEMA_PATH for integration tests") + slog.InfoContext(ctx, + "Set HYPERFLEET_SERVER_OPENAPI_SCHEMA_PATH for integration tests", logger.FieldSchemaPath, schemaPath, + ) } } @@ -62,7 +64,7 @@ func runTestMain(m *testing.M) int { localExit := exitCode go func() { time.Sleep(45 * time.Second) - logger.Error(ctx, "Teardown timed out after 45s, forcing exit") + slog.ErrorContext(ctx, "Teardown timed out after 45s, forcing exit") if localExit == 0 { localExit = 1 } @@ -79,7 +81,7 @@ func terminateContainer(ctx context.Context, pgContainer *postgres.PostgresConta termCtx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() if err := pgContainer.Terminate(termCtx); err != nil { - logger.WithError(ctx, err).Error("Failed to terminate testcontainer") + slog.ErrorContext(ctx, "Failed to terminate testcontainer", "error", err) } } @@ -105,19 +107,19 @@ func startTestcontainer(ctx context.Context) *postgres.PostgresContainer { WithStartupTimeout(60*time.Second)), ) if err != nil { - logger.WithError(ctx, err).Error("Failed to start PostgreSQL testcontainer") + slog.ErrorContext(ctx, "Failed to start PostgreSQL testcontainer", "error", err) os.Exit(1) } host, err := pgContainer.Host(ctx) if err != nil { - logger.WithError(ctx, err).Error("Failed to get testcontainer host") + slog.ErrorContext(ctx, "Failed to get testcontainer host", "error", err) terminateContainer(ctx, pgContainer) os.Exit(1) } mappedPort, err := pgContainer.MappedPort(ctx, "5432/tcp") if err != nil { - logger.WithError(ctx, err).Error("Failed to get testcontainer mapped port") + slog.ErrorContext(ctx, "Failed to get testcontainer mapped port", "error", err) terminateContainer(ctx, pgContainer) os.Exit(1) } @@ -125,6 +127,6 @@ func startTestcontainer(ctx context.Context) *postgres.PostgresContainer { os.Setenv("HYPERFLEET_DATABASE_HOST", host) os.Setenv("HYPERFLEET_DATABASE_PORT", mappedPort.Port()) - logger.With(ctx, "host", host, "port", mappedPort.Port()).Info("PostgreSQL testcontainer started") + slog.InfoContext(ctx, "PostgreSQL testcontainer started", "host", host, "port", mappedPort.Port()) return pgContainer }