From 48268173159b991ad2947de2866d9272cc1255dd Mon Sep 17 00:00:00 2001 From: FZambia Date: Tue, 24 Dec 2024 20:24:48 +0200 Subject: [PATCH] logging improvements --- go.mod | 2 +- go.sum | 4 +-- internal/consuming/kafka.go | 2 +- internal/logging/logging.go | 56 +++++++++++++++++++++++-------- internal/unigrpc/grpc.go | 2 +- internal/unihttpstream/handler.go | 2 +- internal/unisse/handler.go | 2 +- internal/uniws/handler.go | 2 +- internal/usage/usage.go | 2 +- internal/wt/handler.go | 2 +- 10 files changed, 52 insertions(+), 24 deletions(-) diff --git a/go.mod b/go.mod index 49c6dccaa..45e28d363 100644 --- a/go.mod +++ b/go.mod @@ -5,7 +5,7 @@ go 1.23.0 require ( github.com/FZambia/eagle v0.1.0 github.com/FZambia/statik v0.1.2-0.20180217151304-b9f012bb2a1b - github.com/centrifugal/centrifuge v0.33.5-0.20241222164738-7c718f40f348 + github.com/centrifugal/centrifuge v0.33.5-0.20241224182106-98fa466b7243 github.com/centrifugal/protocol v0.13.5-0.20241111155425-6c360178091e github.com/cristalhq/jwt/v5 v5.4.0 github.com/go-viper/mapstructure/v2 v2.2.1 diff --git a/go.sum b/go.sum index 45b4072df..39a64657b 100644 --- a/go.sum +++ b/go.sum @@ -6,8 +6,8 @@ github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= github.com/cenkalti/backoff/v4 v4.3.0 h1:MyRJ/UdXutAwSAT+s3wNd7MfTIcy71VQueUuFK343L8= github.com/cenkalti/backoff/v4 v4.3.0/go.mod h1:Y3VNntkOUPxTVeUxJ/G5vcM//AlwfmyYozVcomhLiZE= -github.com/centrifugal/centrifuge v0.33.5-0.20241222164738-7c718f40f348 h1:F2UZujbtzJwNxcXt6BoXfXFe5NIUkVjYjlvPnzLf8pE= -github.com/centrifugal/centrifuge v0.33.5-0.20241222164738-7c718f40f348/go.mod h1:hKy1+IjduZJge3EDS3NSSZdTpWd4qhz+AlANNfyv/jE= +github.com/centrifugal/centrifuge v0.33.5-0.20241224182106-98fa466b7243 h1:mb42mNCu+SOmEDdC1QyAGyoc/ItG/0F6YO2A847LV7c= +github.com/centrifugal/centrifuge v0.33.5-0.20241224182106-98fa466b7243/go.mod h1:hKy1+IjduZJge3EDS3NSSZdTpWd4qhz+AlANNfyv/jE= github.com/centrifugal/protocol v0.13.5-0.20241111155425-6c360178091e h1:+GbuEwJybDuHz6e8S17t/f0I4aTDnZjk37c0aGNFbwc= github.com/centrifugal/protocol v0.13.5-0.20241111155425-6c360178091e/go.mod h1:7V5vI30VcoxJe4UD87xi7bOsvI0bmEhvbQuMjrFM2L4= github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= diff --git a/internal/consuming/kafka.go b/internal/consuming/kafka.go index 765c4a0b7..2cf9e1c11 100644 --- a/internal/consuming/kafka.go +++ b/internal/consuming/kafka.go @@ -528,7 +528,7 @@ func (pc *partitionConsumer) processRecords(records []*kgo.Record) { retries++ backoffDuration = getNextBackoffDuration(backoffDuration, retries) pc.metrics.errorsTotal.WithLabelValues(pc.name).Inc() - log.Error().Err(err).Str("consumer_name", pc.name).Str("topic", record.Topic).Int32("partition", record.Partition).Dur("next_attempt_in", backoffDuration).Msg("error processing consumed record") + log.Error().Err(err).Str("consumer_name", pc.name).Str("topic", record.Topic).Int32("partition", record.Partition).Str("next_attempt_in", backoffDuration.String()).Msg("error processing consumed record") select { case <-time.After(backoffDuration): case <-pc.partitionCtx.Done(): diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 5ebc9dc16..7f2d73c09 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -1,15 +1,16 @@ package logging import ( + "io" "os" "runtime" "strings" "github.com/centrifugal/centrifugo/v5/internal/config" "github.com/centrifugal/centrifugo/v5/internal/logutils" + "github.com/mattn/go-isatty" "github.com/centrifugal/centrifuge" - "github.com/mattn/go-isatty" "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) @@ -80,8 +81,16 @@ func (h *centrifugeLogHandler) readEntries() { continue } if entry.Fields != nil { + if entry.Error != nil { + l = l.Err(entry.Error) + delete(entry.Fields, "error") + } l.Fields(entry.Fields).Msg(entry.Message) } else { + if entry.Error != nil { + l = l.Err(entry.Error) + delete(entry.Fields, "error") + } l.Msg(entry.Message) } } @@ -95,16 +104,17 @@ func (h *centrifugeLogHandler) Handle(entry centrifuge.LogEntry) { } } -func configureConsoleWriter() { +func configureConsoleWriter() *zerolog.ConsoleWriter { if isTerminalAttached() { - log.Logger = log.Output(zerolog.ConsoleWriter{ + return &zerolog.ConsoleWriter{ Out: os.Stdout, TimeFormat: "2006-01-02 15:04:05", FormatLevel: logutils.ConsoleFormatLevel(), FormatErrFieldName: logutils.ConsoleFormatErrFieldName(), FormatErrFieldValue: logutils.ConsoleFormatErrFieldValue(), - }) + } } + return nil } func isTerminalAttached() bool { @@ -112,23 +122,41 @@ func isTerminalAttached() bool { } func Setup(cfg config.Config) (centrifuge.LogHandler, func()) { - configureConsoleWriter() + var writers []io.Writer + + var file *os.File + if cfg.LogFile != "" { + var err error + file, err = os.OpenFile(cfg.LogFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644) + if err != nil { + log.Fatal().Err(err).Msg("error opening log file") + } + writers = append(writers, file) + } else { + consoleWriter := configureConsoleWriter() + if consoleWriter != nil { + writers = append(writers, consoleWriter) + } else { + writers = append(writers, os.Stderr) + } + } + logLevel, ok := logLevelMatches[strings.ToUpper(cfg.LogLevel)] if !ok { logLevel = zerolog.InfoLevel } zerolog.SetGlobalLevel(logLevel) - if cfg.LogFile != "" { - f, err := os.OpenFile(cfg.LogFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644) - if err != nil { - log.Fatal().Err(err).Msg("error opening log file") - } - log.Logger = log.Output(f) - return newCentrifugeLogHandler().Handle, func() { - _ = f.Close() + + if len(writers) > 0 { + mw := io.MultiWriter(writers...) + log.Logger = log.Output(mw) + } + + return newCentrifugeLogHandler().Handle, func() { + if file != nil { + _ = file.Close() } } - return newCentrifugeLogHandler().Handle, nil } // Enabled checks if a specific logging level is enabled diff --git a/internal/unigrpc/grpc.go b/internal/unigrpc/grpc.go index 2ef68b0a1..72b06c9fa 100644 --- a/internal/unigrpc/grpc.go +++ b/internal/unigrpc/grpc.go @@ -64,7 +64,7 @@ func (s *Service) Consume(req *unistream.ConnectRequest, stream unistream.Centri if logging.Enabled(logging.DebugLevel) { log.Debug().Str("transport", transport.Name()).Str("client", c.ID()).Msg("client connection established") defer func(started time.Time) { - log.Debug().Str("transport", transport.Name()).Str("client", c.ID()).Dur("duration", time.Since(started)).Msg("client connection completed") + log.Debug().Str("transport", transport.Name()).Str("client", c.ID()).Str("duration", time.Since(started).String()).Msg("client connection completed") }(time.Now()) } diff --git a/internal/unihttpstream/handler.go b/internal/unihttpstream/handler.go index 2f020969a..eeb282869 100644 --- a/internal/unihttpstream/handler.go +++ b/internal/unihttpstream/handler.go @@ -73,7 +73,7 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { if logging.Enabled(logging.DebugLevel) { log.Debug().Str("transport", transportName).Str("client", c.ID()).Msg("client connection established") defer func(started time.Time) { - log.Debug().Str("transport", transportName).Str("client", c.ID()).Dur("duration", time.Since(started)).Msg("client connection completed") + log.Debug().Str("transport", transportName).Str("client", c.ID()).Str("duration", time.Since(started).String()).Msg("client connection completed") }(time.Now()) } diff --git a/internal/unisse/handler.go b/internal/unisse/handler.go index 7f9df35a0..a4a1c28eb 100644 --- a/internal/unisse/handler.go +++ b/internal/unisse/handler.go @@ -83,7 +83,7 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { if logging.Enabled(logging.DebugLevel) { log.Debug().Str("transport", transportName).Str("client", c.ID()).Msg("client connection established") defer func(started time.Time) { - log.Debug().Str("transport", transportName).Str("client", c.ID()).Dur("duration", time.Since(started)).Msg("client connection completed") + log.Debug().Str("transport", transportName).Str("client", c.ID()).Str("duration", time.Since(started).String()).Msg("client connection completed") }(time.Now()) } diff --git a/internal/uniws/handler.go b/internal/uniws/handler.go index 144de7328..a063a7b8f 100644 --- a/internal/uniws/handler.go +++ b/internal/uniws/handler.go @@ -142,7 +142,7 @@ func (s *Handler) ServeHTTP(rw http.ResponseWriter, r *http.Request) { if logging.Enabled(logging.DebugLevel) { log.Debug().Str("transport", transportName).Str("client", c.ID()).Msg("client connection established") defer func(started time.Time) { - log.Debug().Str("transport", transportName).Str("client", c.ID()).Dur("duration", time.Since(started)).Msg("client connection completed") + log.Debug().Str("transport", transportName).Str("client", c.ID()).Str("duration", time.Since(started).String()).Msg("client connection completed") }(time.Now()) } diff --git a/internal/usage/usage.go b/internal/usage/usage.go index 6374f1a5b..8a1d3bd05 100644 --- a/internal/usage/usage.go +++ b/internal/usage/usage.go @@ -141,7 +141,7 @@ func (s *Sender) isDev() bool { func (s *Sender) Run(ctx context.Context) error { firstTimeSend := time.Now().Add(initialDelay) if s.isDev() { - log.Debug().Dur("delay", initialDelay).Msg("usage stats: schedule next send") + log.Debug().Str("delay", initialDelay.String()).Msg("usage stats: schedule next send") } // Wait 1/4 of a delay to randomize hourly ticks on different nodes. diff --git a/internal/wt/handler.go b/internal/wt/handler.go index 2a0bb9bbc..1ecfc5a03 100644 --- a/internal/wt/handler.go +++ b/internal/wt/handler.go @@ -64,7 +64,7 @@ func (s *Handler) ServeHTTP(rw http.ResponseWriter, r *http.Request) { if logging.Enabled(logging.DebugLevel) { log.Debug().Str("transport", transportName).Str("client", c.ID()).Msg("client connection established") defer func(started time.Time) { - log.Debug().Str("transport", transportName).Str("client", c.ID()).Dur("duration", time.Since(started)).Msg("client connection completed") + log.Debug().Str("transport", transportName).Str("client", c.ID()).Str("duration", time.Since(started).String()).Msg("client connection completed") }(time.Now()) }