feat: add professional logging with runtime configuration and performance optimization
Implements structured logging package with LOG_LEVEL/LOG_FORMAT env support, debug level guards for hot paths, enriched error messages with actionable context, and stack trace capture for production debugging. Improves observability and reduces log overhead in high-frequency polling loops.
This commit is contained in:
parent
fa21e9c69c
commit
7d422d2909
10 changed files with 865 additions and 49 deletions
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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")
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
|
|
|
|||
307
internal/logging/logging.go
Normal file
307
internal/logging/logging.go
Normal file
|
|
@ -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
|
||||
}
|
||||
476
internal/logging/logging_test.go
Normal file
476
internal/logging/logging_test.go
Normal file
|
|
@ -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")
|
||||
}
|
||||
}
|
||||
|
|
@ -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
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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 {
|
||||
|
|
|
|||
|
|
@ -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")
|
||||
}
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
}
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in a new issue