diff --git a/cmd/pulse/main.go b/cmd/pulse/main.go index 1b7d58f..f8e160e 100644 --- a/cmd/pulse/main.go +++ b/cmd/pulse/main.go @@ -14,10 +14,10 @@ import ( "github.com/rcourtman/pulse-go-rewrite/internal/api" "github.com/rcourtman/pulse-go-rewrite/internal/config" + "github.com/rcourtman/pulse-go-rewrite/internal/logging" _ "github.com/rcourtman/pulse-go-rewrite/internal/mock" // Import for init() to run "github.com/rcourtman/pulse-go-rewrite/internal/monitoring" "github.com/rcourtman/pulse-go-rewrite/internal/websocket" - "github.com/rs/zerolog" "github.com/rs/zerolog/log" "github.com/spf13/cobra" ) @@ -70,9 +70,12 @@ func main() { } func runServer() { - // Initialize logger - zerolog.TimeFieldFormat = zerolog.TimeFormatUnix - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}) + // Initialize logger with baseline defaults for early startup logs + logging.Init(logging.Config{ + Format: "auto", + Level: "info", + Component: "pulse", + }) // Check for auto-import on first startup if shouldAutoImport() { @@ -87,6 +90,13 @@ func runServer() { log.Fatal().Err(err).Msg("Failed to load configuration") } + // Re-initialize logging with configuration-driven settings + logging.Init(logging.Config{ + Format: cfg.LogFormat, + Level: cfg.LogLevel, + Component: "pulse", + }) + log.Info().Msg("Starting Pulse monitoring server") // Create context that cancels on interrupt diff --git a/internal/api/security_oidc.go b/internal/api/security_oidc.go index 90bf830..3d211c0 100644 --- a/internal/api/security_oidc.go +++ b/internal/api/security_oidc.go @@ -27,7 +27,7 @@ func (r *Router) handleGetOIDCConfig(w http.ResponseWriter, req *http.Request) { response := makeOIDCResponse(cfg, r.config.PublicURL) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - log.Error().Err(err).Msg("Failed to encode OIDC configuration response") + log.Error().Err(err).Msg("Failed to encode OIDC configuration response; returning HTTP 500 to caller") } } @@ -105,7 +105,7 @@ func (r *Router) handleUpdateOIDCConfig(w http.ResponseWriter, req *http.Request response := makeOIDCResponse(updated, r.config.PublicURL) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(response); err != nil { - log.Error().Err(err).Msg("Failed to encode OIDC configuration response") + log.Error().Err(err).Msg("Failed to encode OIDC configuration response; returning HTTP 500 to caller") } } diff --git a/internal/config/config.go b/internal/config/config.go index d610185..54db08b 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -21,8 +21,9 @@ import ( "github.com/google/uuid" "github.com/joho/godotenv" + "github.com/pkg/errors" "github.com/rcourtman/pulse-go-rewrite/internal/auth" - "github.com/rs/zerolog" + "github.com/rcourtman/pulse-go-rewrite/internal/logging" "github.com/rs/zerolog/log" ) @@ -90,6 +91,7 @@ type Config struct { // Logging settings LogLevel string `envconfig:"LOG_LEVEL" default:"info"` + LogFormat string `envconfig:"LOG_FORMAT" default:"auto"` // "json", "console", or "auto" LogFile string `envconfig:"LOG_FILE" default:""` LogMaxSize int `envconfig:"LOG_MAX_SIZE" default:"100"` // MB LogMaxAge int `envconfig:"LOG_MAX_AGE" default:"30"` // days @@ -271,6 +273,7 @@ func Load() (*Config, error) { AdaptivePollingMinInterval: 5 * time.Second, AdaptivePollingMaxInterval: 5 * time.Minute, LogLevel: "info", + LogFormat: "auto", LogMaxSize: 100, LogMaxAge: 30, LogCompress: true, @@ -743,6 +746,11 @@ func Load() (*Config, error) { cfg.EnvOverrides["logLevel"] = true log.Info().Str("level", logLevel).Msg("Log level overridden by LOG_LEVEL env var") } + if logFormat := os.Getenv("LOG_FORMAT"); logFormat != "" { + cfg.LogFormat = logFormat + cfg.EnvOverrides["logFormat"] = true + log.Info().Str("format", logFormat).Msg("Log format overridden by LOG_FORMAT env var") + } if connectionTimeout := os.Getenv("CONNECTION_TIMEOUT"); connectionTimeout != "" { if d, err := time.ParseDuration(connectionTimeout + "s"); err == nil { cfg.ConnectionTimeout = d @@ -773,21 +781,16 @@ func Load() (*Config, error) { cfg.OIDC.ApplyDefaults(cfg.PublicURL) - // Set log level - switch cfg.LogLevel { - case "debug": - zerolog.SetGlobalLevel(zerolog.DebugLevel) - case "warn": - zerolog.SetGlobalLevel(zerolog.WarnLevel) - case "error": - zerolog.SetGlobalLevel(zerolog.ErrorLevel) - default: - zerolog.SetGlobalLevel(zerolog.InfoLevel) // Default to info level - } + // Initialize logging with configuration values + logging.Init(logging.Config{ + Format: cfg.LogFormat, + Level: cfg.LogLevel, + Component: "pulse-config", + }) // Validate configuration if err := cfg.Validate(); err != nil { - return nil, fmt.Errorf("invalid configuration: %w", err) + return nil, errors.Wrap(err, "load config: invalid configuration") } return cfg, nil diff --git a/internal/config/settings.go b/internal/config/settings.go index 5b09154..de6c494 100644 --- a/internal/config/settings.go +++ b/internal/config/settings.go @@ -38,11 +38,12 @@ type MonitoringSettings struct { // LoggingSettings contains logging configuration type LoggingSettings struct { - Level string `json:"level" yaml:"level" mapstructure:"level"` // debug, info, warn, error - File string `json:"file" yaml:"file" mapstructure:"file"` // log file path - MaxSize int `json:"maxSize" yaml:"maxSize" mapstructure:"maxSize"` // MB + Level string `json:"level" yaml:"level" mapstructure:"level"` // debug, info, warn, error + Format string `json:"format" yaml:"format" mapstructure:"format"` // json, console, auto + File string `json:"file" yaml:"file" mapstructure:"file"` // log file path + MaxSize int `json:"maxSize" yaml:"maxSize" mapstructure:"maxSize"` // MB MaxBackups int `json:"maxBackups" yaml:"maxBackups" mapstructure:"maxBackups"` - MaxAge int `json:"maxAge" yaml:"maxAge" mapstructure:"maxAge"` // days + MaxAge int `json:"maxAge" yaml:"maxAge" mapstructure:"maxAge"` // days Compress bool `json:"compress" yaml:"compress" mapstructure:"compress"` } @@ -77,6 +78,7 @@ func DefaultSettings() *Settings { }, Logging: LoggingSettings{ Level: "info", + Format: "auto", File: "/opt/pulse/pulse.log", MaxSize: 100, // 100MB MaxBackups: 5, diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..b94b4c0 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,307 @@ +package logging + +import ( + "context" + "fmt" + "io" + "os" + "strings" + "sync" + "time" + + "github.com/google/uuid" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" + "github.com/rs/zerolog/pkgerrors" + "golang.org/x/term" +) + +type ctxKey string + +const ( + requestIDKey ctxKey = "logging_request_id" + loggerKey ctxKey = "logging_logger" +) + +// Config controls logger initialization. +type Config struct { + Format string // "json", "console", or "auto" + Level string // "debug", "info", "warn", "error" + Component string // optional component name +} + +// Option customizes logger construction. +type Option func(*options) + +type options struct { + writer io.Writer + fields map[string]interface{} + withCaller bool +} + +var ( + mu sync.RWMutex + baseLogger zerolog.Logger + baseWriter io.Writer = os.Stderr + baseComponent string + + defaultTimeFmt = time.RFC3339 +) + +func init() { + baseLogger = zerolog.New(baseWriter).With().Timestamp().Logger() + log.Logger = baseLogger +} + +// Init configures zerolog globals and establishes the package baseline logger. +func Init(cfg Config) zerolog.Logger { + mu.Lock() + defer mu.Unlock() + + zerolog.TimeFieldFormat = defaultTimeFmt + zerolog.SetGlobalLevel(parseLevel(cfg.Level)) + zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack + + writer := selectWriter(cfg.Format) + component := strings.TrimSpace(cfg.Component) + + contextBuilder := zerolog.New(writer).With().Timestamp() + if component != "" { + contextBuilder = contextBuilder.Str("component", component) + } + + baseLogger = contextBuilder.Logger() + baseWriter = writer + baseComponent = component + log.Logger = baseLogger + + return baseLogger +} + +// InitFromConfig initialises logging with environment overrides. +func InitFromConfig(ctx context.Context, cfg Config) (zerolog.Logger, error) { + if cfg.Level == "" { + cfg.Level = "info" + } + if cfg.Format == "" { + cfg.Format = "auto" + } + + if envLevel := os.Getenv("LOG_LEVEL"); envLevel != "" { + cfg.Level = envLevel + } + if envFormat := os.Getenv("LOG_FORMAT"); envFormat != "" { + cfg.Format = envFormat + } + + if !isValidLevel(cfg.Level) { + return zerolog.Logger{}, fmt.Errorf("invalid log level %q: must be debug, info, warn, or error", cfg.Level) + } + + format := strings.ToLower(strings.TrimSpace(cfg.Format)) + if format != "" && format != "json" && format != "console" && format != "auto" { + return zerolog.Logger{}, fmt.Errorf("invalid log format %q: must be json, console, or auto", cfg.Format) + } + + logger := Init(cfg) + return logger, nil +} + +// IsLevelEnabled reports whether the provided level is enabled for logging. +func IsLevelEnabled(level zerolog.Level) bool { + return level >= zerolog.GlobalLevel() +} + +// New creates a logger tailored to a specific component. +func New(component string, opts ...Option) zerolog.Logger { + cfg := collectOptions(opts...) + + mu.RLock() + globalWriter := baseWriter + globalComponent := baseComponent + mu.RUnlock() + + writer := cfg.writer + if writer == nil { + writer = globalWriter + } + + component = strings.TrimSpace(component) + if component == "" { + component = globalComponent + } + + logger := zerolog.New(writer) + contextBuilder := logger.With().Timestamp() + + if component != "" { + contextBuilder = contextBuilder.Str("component", component) + } + if len(cfg.fields) > 0 { + contextBuilder = contextBuilder.Fields(cfg.fields) + } + if cfg.withCaller { + contextBuilder = contextBuilder.Caller() + } + + return contextBuilder.Logger() +} + +// WithCaller enables caller logging. +func WithCaller() Option { + return func(o *options) { + o.withCaller = true + } +} + +// WithWriter overrides the logger writer. +func WithWriter(w io.Writer) Option { + return func(o *options) { + if w != nil { + o.writer = w + } + } +} + +// WithFields adds static fields to the logger. +func WithFields(fields map[string]interface{}) Option { + return func(o *options) { + if len(fields) == 0 { + return + } + if o.fields == nil { + o.fields = make(map[string]interface{}, len(fields)) + } + for k, v := range fields { + o.fields[k] = v + } + } +} + +// FromContext returns a logger enriched with context metadata. +func FromContext(ctx context.Context) zerolog.Logger { + if ctx == nil { + return getBaseLogger() + } + + if existing, ok := ctx.Value(loggerKey).(zerolog.Logger); ok { + return enrichWithRequestID(existing, ctx) + } + + return enrichWithRequestID(getBaseLogger(), ctx) +} + +// WithLogger stores a logger on the context. +func WithLogger(ctx context.Context, logger zerolog.Logger) context.Context { + if ctx == nil { + ctx = context.Background() + } + return context.WithValue(ctx, loggerKey, logger) +} + +// WithRequestID stores (or generates) a request ID on the context. +func WithRequestID(ctx context.Context, id string) (context.Context, string) { + if ctx == nil { + ctx = context.Background() + } + id = strings.TrimSpace(id) + if id == "" { + id = uuid.NewString() + } + return context.WithValue(ctx, requestIDKey, id), id +} + +// GetRequestID retrieves the request ID from context. +func GetRequestID(ctx context.Context) string { + if ctx == nil { + return "" + } + if id, ok := ctx.Value(requestIDKey).(string); ok { + return id + } + return "" +} + +// NewRequestID creates a new UUID string. +func NewRequestID() string { + return uuid.NewString() +} + +func collectOptions(opts ...Option) options { + cfg := options{} + for _, opt := range opts { + if opt != nil { + opt(&cfg) + } + } + return cfg +} + +func parseLevel(level string) zerolog.Level { + switch strings.ToLower(strings.TrimSpace(level)) { + case "debug": + return zerolog.DebugLevel + case "warn": + return zerolog.WarnLevel + case "error": + return zerolog.ErrorLevel + default: + return zerolog.InfoLevel + } +} + +func isValidLevel(level string) bool { + switch strings.ToLower(strings.TrimSpace(level)) { + case "debug", "info", "warn", "error": + return true + default: + return false + } +} + +func selectWriter(format string) io.Writer { + format = strings.ToLower(strings.TrimSpace(format)) + switch format { + case "console": + return newConsoleWriter(os.Stderr) + case "json": + return os.Stderr + case "auto", "": + if isTerminal(os.Stderr) { + return newConsoleWriter(os.Stderr) + } + return os.Stderr + default: + return os.Stderr + } +} + +func newConsoleWriter(out io.Writer) io.Writer { + return zerolog.ConsoleWriter{ + Out: out, + TimeFormat: defaultTimeFmt, + } +} + +func isTerminal(file *os.File) bool { + if file == nil { + return false + } + return term.IsTerminal(int(file.Fd())) +} + +func getBaseLogger() zerolog.Logger { + mu.RLock() + defer mu.RUnlock() + return baseLogger +} + +func enrichWithRequestID(logger zerolog.Logger, ctx context.Context) zerolog.Logger { + if ctx == nil { + return logger + } + if id := GetRequestID(ctx); id != "" { + return logger.With().Str("request_id", id).Logger() + } + return logger +} diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go new file mode 100644 index 0000000..2bd9588 --- /dev/null +++ b/internal/logging/logging_test.go @@ -0,0 +1,476 @@ +package logging + +import ( + "bytes" + "context" + "encoding/json" + "io" + "os" + "reflect" + "strings" + "sync" + "testing" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +func resetLoggingState() { + mu.Lock() + defer mu.Unlock() + + baseWriter = os.Stderr + baseComponent = "" + baseLogger = zerolog.New(baseWriter).With().Timestamp().Logger() + log.Logger = baseLogger + zerolog.TimeFieldFormat = defaultTimeFmt + zerolog.SetGlobalLevel(zerolog.InfoLevel) +} + +func readJSONLine(t *testing.T, buf *bytes.Buffer) map[string]interface{} { + t.Helper() + + line := strings.TrimSpace(buf.String()) + if idx := strings.IndexByte(line, '\n'); idx >= 0 { + line = line[:idx] + } + if line == "" { + t.Fatalf("expected log output, got empty string") + } + + var event map[string]interface{} + if err := json.Unmarshal([]byte(line), &event); err != nil { + t.Fatalf("failed to unmarshal log line: %v", err) + } + return event +} + +func TestInitJSONFormatSetsLevelAndComponent(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "debug", + Component: "apiserver", + }) + + mu.RLock() + defer mu.RUnlock() + + if baseWriter != os.Stderr { + t.Fatalf("expected base writer to be os.Stderr, got %#v", baseWriter) + } + + if zerolog.GlobalLevel() != zerolog.DebugLevel { + t.Fatalf("expected global level debug, got %s", zerolog.GlobalLevel()) + } + + if baseComponent != "apiserver" { + t.Fatalf("expected base component apiserver, got %s", baseComponent) + } + + if !reflect.DeepEqual(log.Logger, baseLogger) { + t.Fatal("expected global log.Logger to match baseLogger") + } +} + +func TestInitConsoleFormatUsesConsoleWriter(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "console", + Level: "info", + }) + + mu.RLock() + defer mu.RUnlock() + + if _, ok := baseWriter.(zerolog.ConsoleWriter); !ok { + t.Fatalf("expected console writer, got %#v", baseWriter) + } +} + +func TestInitAutoFormatWithPipe(t *testing.T) { + t.Cleanup(resetLoggingState) + + origStderr := os.Stderr + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("failed to create pipe: %v", err) + } + os.Stderr = w + defer func() { + os.Stderr = origStderr + _ = r.Close() + _ = w.Close() + }() + + Init(Config{ + Format: "auto", + Level: "info", + }) + + mu.RLock() + defer mu.RUnlock() + + if baseWriter != w { + t.Fatalf("expected base writer to use provided pipe, got %#v", baseWriter) + } +} + +func TestNewLoggerWithComponentAndFields(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + Component: "root", + }) + + var buf bytes.Buffer + logger := New("worker", WithWriter(&buf), WithFields(map[string]interface{}{ + "request": "sync", + })) + + logger.Info().Msg("processing") + + event := readJSONLine(t, &buf) + + if event["component"] != "worker" { + t.Fatalf("expected component worker, got %v", event["component"]) + } + if event["request"] != "sync" { + t.Fatalf("expected request field, got %v", event["request"]) + } + if event["level"] != "info" { + t.Fatalf("expected level info, got %v", event["level"]) + } + if event["message"] != "processing" { + t.Fatalf("expected message processing, got %v", event["message"]) + } +} + +func TestNewLoggerInheritsComponentWhenEmpty(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + Component: "core", + }) + + var buf bytes.Buffer + logger := New("", WithWriter(&buf)) + logger.Warn().Msg("warn") + + event := readJSONLine(t, &buf) + if event["component"] != "core" { + t.Fatalf("expected inherited component core, got %v", event["component"]) + } +} + +func TestNewLoggerWithCaller(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + }) + + var buf bytes.Buffer + logger := New("svc", WithWriter(&buf), WithCaller()) + logger.Error().Msg("boom") + + event := readJSONLine(t, &buf) + caller, ok := event["caller"].(string) + if !ok || !strings.Contains(caller, "logging_test.go") { + t.Fatalf("expected caller information, got %v", event["caller"]) + } +} + +func TestNewLoggerWithCustomWriter(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + }) + + var buf bytes.Buffer + logger := New("custom", WithWriter(&buf)) + logger.Info().Msg("hello") + + if buf.Len() == 0 { + t.Fatal("expected output on custom writer") + } +} + +func TestContextHelpersWithRequestID(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + }) + + ctx := context.Background() + ctx, generated := WithRequestID(ctx, "") + if generated == "" { + t.Fatal("expected generated request id") + } + if got := GetRequestID(ctx); got != generated { + t.Fatalf("expected stored request id %s, got %s", generated, got) + } + + var buf bytes.Buffer + logger := New("api", WithWriter(&buf)) + ctx = WithLogger(ctx, logger) + + info := FromContext(ctx) + info.Info().Msg("ctx-log") + + event := readJSONLine(t, &buf) + if event["request_id"] != generated { + t.Fatalf("expected request_id %s, got %v", generated, event["request_id"]) + } +} + +func TestContextHelpersWithExistingLogger(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "debug", + }) + + var buf bytes.Buffer + base := New("svc", WithWriter(&buf)) + ctx := WithLogger(context.Background(), base) + ctx, id := WithRequestID(ctx, "custom-123") + + logger := FromContext(ctx) + logger.Debug().Msg("debug") + + event := readJSONLine(t, &buf) + if event["component"] != "svc" { + t.Fatalf("expected component svc, got %v", event["component"]) + } + if event["request_id"] != "custom-123" { + t.Fatalf("expected request_id custom-123, got %v", event["request_id"]) + } + if event["level"] != "debug" { + t.Fatalf("expected level debug, got %v", event["level"]) + } + if id != "custom-123" { + t.Fatalf("expected returned id to match input, got %s", id) + } +} + +func TestWithLoggerNilContext(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{}) + + ctx := WithLogger(nil, New("svc", WithWriter(io.Discard))) + if ctx == nil { + t.Fatal("expected non-nil context") + } +} + +func TestWithRequestIDTrimsWhitespace(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{}) + + ctx, id := WithRequestID(context.Background(), " ") + if id == "" { + t.Fatal("expected generated id for whitespace input") + } + if GetRequestID(ctx) != id { + t.Fatalf("expected context request id %s, got %s", id, GetRequestID(ctx)) + } +} + +func TestFromContextWithoutRequestID(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + }) + + var buf bytes.Buffer + mu.Lock() + baseLogger = zerolog.New(&buf).With().Timestamp().Logger() + baseWriter = &buf + baseComponent = "" + log.Logger = baseLogger + mu.Unlock() + + base := FromContext(context.Background()) + base.Info().Msg("no-request") + + event := readJSONLine(t, &buf) + if _, ok := event["request_id"]; ok { + t.Fatalf("did not expect request_id, got %v", event["request_id"]) + } +} + +func TestNewLoggerWithoutComponentOmitsField(t *testing.T) { + t.Cleanup(resetLoggingState) + + Init(Config{ + Format: "json", + Level: "info", + }) + + var buf bytes.Buffer + logger := New("", WithWriter(&buf)) + logger.Info().Msg("no-component") + + event := readJSONLine(t, &buf) + if _, exists := event["component"]; exists { + t.Fatalf("did not expect component field, got %v", event["component"]) + } +} + +func TestInitThreadSafety(t *testing.T) { + t.Cleanup(resetLoggingState) + + var wg sync.WaitGroup + configs := []Config{ + {Format: "json", Level: "debug", Component: "worker"}, + {Format: "json", Level: "warn", Component: "api"}, + } + + for i := 0; i < 50; i++ { + wg.Add(1) + go func(idx int) { + defer wg.Done() + Init(configs[idx%len(configs)]) + }(i) + } + wg.Wait() + + mu.RLock() + defer mu.RUnlock() + + // Ensure baseLogger is valid and global logger matches it. + if reflect.DeepEqual(baseLogger, zerolog.Logger{}) { + t.Fatal("expected initialized base logger") + } + if !reflect.DeepEqual(log.Logger, baseLogger) { + t.Fatal("expected global log.Logger to match baseLogger after concurrent init") + } +} + +func TestInitFromConfigWithDefaults(t *testing.T) { + t.Cleanup(resetLoggingState) + + logger, err := InitFromConfig(context.Background(), Config{ + Component: "test", + }) + if err != nil { + t.Fatalf("expected no error, got %v", err) + } + + if reflect.DeepEqual(logger, zerolog.Logger{}) { + t.Fatal("expected initialized logger") + } + + if zerolog.GlobalLevel() != zerolog.InfoLevel { + t.Fatalf("expected default info level, got %s", zerolog.GlobalLevel()) + } +} + +func TestInitFromConfigWithEnvOverrides(t *testing.T) { + t.Cleanup(resetLoggingState) + t.Cleanup(func() { + os.Unsetenv("LOG_LEVEL") + os.Unsetenv("LOG_FORMAT") + }) + + os.Setenv("LOG_LEVEL", "debug") + os.Setenv("LOG_FORMAT", "json") + + logger, err := InitFromConfig(context.Background(), Config{ + Level: "info", + Format: "console", + Component: "test", + }) + if err != nil { + t.Fatalf("expected no error, got %v", err) + } + + if reflect.DeepEqual(logger, zerolog.Logger{}) { + t.Fatal("expected initialized logger") + } + + // Env override should set debug level + if zerolog.GlobalLevel() != zerolog.DebugLevel { + t.Fatalf("expected debug level from env override, got %s", zerolog.GlobalLevel()) + } + + // Format should be JSON (from env) + mu.RLock() + defer mu.RUnlock() + if _, ok := baseWriter.(zerolog.ConsoleWriter); ok { + t.Fatal("expected JSON writer from env override, got console writer") + } +} + +func TestInitFromConfigInvalidLevel(t *testing.T) { + t.Cleanup(resetLoggingState) + + _, err := InitFromConfig(context.Background(), Config{ + Level: "invalid", + Format: "json", + }) + if err == nil { + t.Fatal("expected error for invalid level") + } + if !strings.Contains(err.Error(), "invalid log level") { + t.Fatalf("expected invalid level error, got %v", err) + } +} + +func TestInitFromConfigInvalidFormat(t *testing.T) { + t.Cleanup(resetLoggingState) + + _, err := InitFromConfig(context.Background(), Config{ + Level: "info", + Format: "invalid", + }) + if err == nil { + t.Fatal("expected error for invalid format") + } + if !strings.Contains(err.Error(), "invalid log format") { + t.Fatalf("expected invalid format error, got %v", err) + } +} + +func TestIsLevelEnabled(t *testing.T) { + t.Cleanup(resetLoggingState) + + // Set global level to Info + zerolog.SetGlobalLevel(zerolog.InfoLevel) + + if !IsLevelEnabled(zerolog.InfoLevel) { + t.Fatal("expected info level to be enabled") + } + if !IsLevelEnabled(zerolog.WarnLevel) { + t.Fatal("expected warn level to be enabled") + } + if !IsLevelEnabled(zerolog.ErrorLevel) { + t.Fatal("expected error level to be enabled") + } + if IsLevelEnabled(zerolog.DebugLevel) { + t.Fatal("expected debug level to be disabled") + } + + // Change to debug level + zerolog.SetGlobalLevel(zerolog.DebugLevel) + if !IsLevelEnabled(zerolog.DebugLevel) { + t.Fatal("expected debug level to be enabled after setting global level") + } +} diff --git a/internal/monitoring/container_disk_usage.go b/internal/monitoring/container_disk_usage.go index 28b1a5e..38c1a55 100644 --- a/internal/monitoring/container_disk_usage.go +++ b/internal/monitoring/container_disk_usage.go @@ -92,7 +92,7 @@ func (m *Monitor) collectContainerRootUsage(ctx context.Context, client PVEClien Err(err). Str("node", node). Str("storage", storage.Storage). - Msg("Unable to query storage content for container disk overrides") + Msg("Container disk usage query failed; metrics for instance omitted this cycle") continue } diff --git a/internal/monitoring/monitor_polling.go b/internal/monitoring/monitor_polling.go index 4b20c7e..30b5968 100644 --- a/internal/monitoring/monitor_polling.go +++ b/internal/monitoring/monitor_polling.go @@ -11,8 +11,10 @@ import ( "time" "github.com/rcourtman/pulse-go-rewrite/internal/errors" + "github.com/rcourtman/pulse-go-rewrite/internal/logging" "github.com/rcourtman/pulse-go-rewrite/internal/models" "github.com/rcourtman/pulse-go-rewrite/pkg/proxmox" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) @@ -231,7 +233,7 @@ func (m *Monitor) pollVMsWithNodes(ctx context.Context, instanceName string, cli vms, err := client.GetVMs(ctx, n.Node) if err != nil { monErr := errors.NewMonitorError(errors.ErrorTypeAPI, "get_vms", instanceName, err).WithNode(n.Node) - log.Error().Err(monErr).Str("node", n.Node).Msg("Failed to get VMs") + log.Error().Err(monErr).Str("node", n.Node).Msg("Failed to get VMs; deferring node poll until next cycle") resultChan <- nodeResult{node: n.Node, err: err} return } @@ -459,28 +461,34 @@ func (m *Monitor) pollVMsWithNodes(ctx context.Context, instanceName string, cli // The cluster/resources endpoint always returns 0 for disk usage if vm.Status == "running" && vmStatus != nil && diskTotal > 0 { // Log the initial state - log.Debug(). - Str("instance", instanceName). - Str("vm", vm.Name). - Int("vmid", vm.VMID). - Int("agent", vmStatus.Agent). - Uint64("diskUsed", diskUsed). - Uint64("diskTotal", diskTotal). - Msg("VM has 0 disk usage, checking guest agent") - - // Check if agent is enabled - if vmStatus.Agent == 0 { - diskStatusReason = "agent-disabled" - log.Debug(). - Str("instance", instanceName). - Str("vm", vm.Name). - Msg("Guest agent disabled in VM config") - } else if vmStatus.Agent > 0 || diskUsed == 0 { + if logging.IsLevelEnabled(zerolog.DebugLevel) { log.Debug(). Str("instance", instanceName). Str("vm", vm.Name). Int("vmid", vm.VMID). - Msg("Guest agent enabled, fetching filesystem info") + Int("agent", vmStatus.Agent). + Uint64("diskUsed", diskUsed). + Uint64("diskTotal", diskTotal). + Msg("VM has 0 disk usage, checking guest agent") + } + + // Check if agent is enabled + if vmStatus.Agent == 0 { + diskStatusReason = "agent-disabled" + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug(). + Str("instance", instanceName). + Str("vm", vm.Name). + Msg("Guest agent disabled in VM config") + } + } else if vmStatus.Agent > 0 || diskUsed == 0 { + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug(). + Str("instance", instanceName). + Str("vm", vm.Name). + Int("vmid", vm.VMID). + Msg("Guest agent enabled, fetching filesystem info") + } statusCtx, cancel := context.WithTimeout(ctx, 5*time.Second) if fsInfo, err := client.GetVMFSInfo(statusCtx, n.Node, vm.VMID); err != nil { diff --git a/internal/monitoring/poller.go b/internal/monitoring/poller.go index 89f5bbd..a5a9813 100644 --- a/internal/monitoring/poller.go +++ b/internal/monitoring/poller.go @@ -5,8 +5,10 @@ import ( "time" "github.com/rcourtman/pulse-go-rewrite/internal/errors" + "github.com/rcourtman/pulse-go-rewrite/internal/logging" "github.com/rcourtman/pulse-go-rewrite/pkg/pbs" "github.com/rcourtman/pulse-go-rewrite/pkg/pmg" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) @@ -64,16 +66,22 @@ func (p *PollerPool) Start(ctx context.Context) { // worker processes polling tasks func (p *PollerPool) worker(ctx context.Context, id int) { - log.Debug().Int("worker", id).Msg("Poller worker started") + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug().Int("worker", id).Msg("Poller worker started") + } for { select { case <-ctx.Done(): - log.Debug().Int("worker", id).Msg("Poller worker stopped") + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug().Int("worker", id).Msg("Poller worker stopped") + } return case task, ok := <-p.tasksChan: if !ok { - log.Debug().Int("worker", id).Msg("Task channel closed, worker stopping") + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug().Int("worker", id).Msg("Task channel closed, worker stopping") + } return } @@ -91,7 +99,9 @@ func (p *PollerPool) worker(ctx context.Context, id int) { return default: // Channel might be closed, just continue - log.Debug().Int("worker", id).Msg("Results channel appears closed, skipping result") + if logging.IsLevelEnabled(zerolog.DebugLevel) { + log.Debug().Int("worker", id).Msg("Results channel appears closed, skipping result") + } } } } @@ -162,7 +172,7 @@ func (p *PollerPool) collectResults(ctx context.Context) { Str("instance", result.InstanceName). Str("type", result.InstanceType). Dur("duration", duration). - Msg("Polling failed") + Msg("Polling failed; request will be retried on next cycle") } } } diff --git a/pkg/proxmox/cluster_client.go b/pkg/proxmox/cluster_client.go index a7a1f7f..41fc84a 100644 --- a/pkg/proxmox/cluster_client.go +++ b/pkg/proxmox/cluster_client.go @@ -302,7 +302,7 @@ func (cc *ClusterClient) getHealthyClient(ctx context.Context) (*Client, error) Str("cluster", cc.name). Str("endpoint", selectedEndpoint). Err(testErr). - Msg("Cluster endpoint failed connectivity test") + Msg("Failed to connect to Proxmox endpoint; endpoint removed from rotation until next refresh") return nil, fmt.Errorf("endpoint %s failed connectivity test: %w", selectedEndpoint, testErr) } }