From 0094cc0d9c88651090c5f4e924100001e04308e1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Torbj=C3=B6rn=20Einarson?= Date: Mon, 16 Oct 2023 21:58:46 +0200 Subject: [PATCH] feat: change logger from zerolog to slog and add pretty handler --- .vscode/settings.json | 1 + CHANGELOG.md | 1 + cmd/dashfetcher/app/fetcher.go | 32 ++-- cmd/dashfetcher/main.go | 25 +-- cmd/livesim2/app/asset.go | 26 +-- cmd/livesim2/app/config.go | 4 +- cmd/livesim2/app/handler_assets.go | 5 +- cmd/livesim2/app/handler_index_test.go | 4 +- cmd/livesim2/app/handler_livesim.go | 24 +-- cmd/livesim2/app/handler_livesim_test.go | 4 +- cmd/livesim2/app/handler_urlgen.go | 5 +- cmd/livesim2/app/ipreqlimit.go | 11 +- cmd/livesim2/app/livesegment.go | 13 +- cmd/livesim2/app/livesegment_test.go | 7 +- cmd/livesim2/app/server.go | 18 +-- cmd/livesim2/app/server_test.go | 2 +- cmd/livesim2/app/start.go | 14 +- cmd/livesim2/app/timesubs.go | 8 +- cmd/livesim2/app/timesubs_test.go | 4 +- cmd/livesim2/main.go | 10 +- go.mod | 9 +- go.sum | 25 ++- pkg/logging/http_handler.go | 11 +- pkg/logging/http_handler_test.go | 10 +- pkg/logging/init.go | 53 +++---- pkg/logging/init_windows.go | 48 ------ pkg/logging/slog.go | 127 +++++++++++++++ pkg/logging/slog_test.go | 36 +++++ pkg/logging/zerolog.go | 194 ----------------------- pkg/logging/zerolog_test.go | 36 ----- 30 files changed, 322 insertions(+), 445 deletions(-) delete mode 100644 pkg/logging/init_windows.go create mode 100644 pkg/logging/slog.go create mode 100644 pkg/logging/slog_test.go delete mode 100644 pkg/logging/zerolog.go delete mode 100644 pkg/logging/zerolog_test.go diff --git a/.vscode/settings.json b/.vscode/settings.json index 782d07f..9eb6b01 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -80,6 +80,7 @@ "prettylog", "promhttp", "proxied", + "proxying", "repdata", "repdataroot", "reqcount", diff --git a/CHANGELOG.md b/CHANGELOG.md index 9dc5780..b39a02c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## Changed - Upgrade to Go 1.21 +- Changed logging to slog instead of zerolog. Log levels limited to DEBUG, INFO, WARN, ERROR. ### Fixed diff --git a/cmd/dashfetcher/app/fetcher.go b/cmd/dashfetcher/app/fetcher.go index 9cdb73f..7d7692a 100644 --- a/cmd/dashfetcher/app/fetcher.go +++ b/cmd/dashfetcher/app/fetcher.go @@ -8,6 +8,7 @@ import ( "context" "fmt" "io" + "log/slog" "net/http" "net/url" "os" @@ -19,7 +20,6 @@ import ( "github.com/Dash-Industry-Forum/livesim2/internal" m "github.com/Eyevinn/dash-mpd/mpd" - "github.com/rs/zerolog/log" ) type Options struct { @@ -50,8 +50,10 @@ func Fetch(o *Options) error { return fmt.Errorf("createDir: %w", err) } cnt, err := start(ctx, o) - log.Info().Int("nrFiles", cnt.total()).Int("nrExisting", cnt.nrExisting). - Int("nrDownloaded", cnt.nrDownloaded).Int("nrErrors", cnt.nrErrors).Msg("download results") + slog.Info("download results", "nrFiles", cnt.total(), + "nrExisting", cnt.nrExisting, + "nrDownloaded", cnt.nrDownloaded, + "nrErrors", cnt.nrErrors) return err } @@ -121,7 +123,7 @@ func start(ctx context.Context, o *Options) (counts, error) { case strings.Contains(media, "$Time$"): cnt = downloadSegmentTimeLineWithTime(ctx, stl, media, outDir, baseURL, cnt, o.Force) case strings.Contains(media, "$Number$"): - log.Warn().Msg("SegmentTimeline with $Number$ not yet supported") + slog.Warn("SegmentTimeline with $Number$ not yet supported") // downloadSegmentTimeLineWithNumber default: return cnt, fmt.Errorf("strange media for SegmentTimeline") @@ -145,7 +147,7 @@ func start(ctx context.Context, o *Options) (counts, error) { func downloadMPD(ctx context.Context, mpdURL, outDir, mpdName string, cnt counts, force bool) (counts, error) { outPath := path.Join(outDir, mpdName) if fileExists(outPath) && !force { - log.Info().Str("path", outPath).Str("url", mpdURL).Msg("file already exists. Skipping") + slog.Info("file already exists. Skipping", "path", outPath, "url", mpdURL) cnt.nrExisting++ } else { err := downloadToFile(ctx, mpdURL, outPath) @@ -155,7 +157,7 @@ func downloadMPD(ctx context.Context, mpdURL, outDir, mpdName string, cnt counts } err = internal.WriteMPDData(outDir, mpdName, mpdURL) if err != nil { - log.Warn().Err(err).Msg("could not write mdlist file") + slog.Warn("could not write mpdlist file", "error", err) } } return cnt, nil @@ -166,7 +168,7 @@ func downloadInit(ctx context.Context, segTmpl *m.SegmentTemplateType, outDir, b p := path.Join(outDir, initStr) cnt, err := downloadAndCount(ctx, u, p, cnt, force) if err != nil { - log.Warn().Err(err).Msg("download init segment") + slog.Warn("download init segment", "error", err) } return cnt } @@ -183,7 +185,7 @@ func downloadSegmentTimeLineWithTime(ctx context.Context, stl *m.SegmentTimeline p := path.Join(outDir, mPart) cnt, err = downloadAndCount(ctx, u, p, cnt, force) if err != nil { - log.Warn().Err(err).Msg("download file") + slog.Warn("download file", "error", err) } dur := segItvl.D startTime += dur @@ -193,7 +195,7 @@ func downloadSegmentTimeLineWithTime(ctx context.Context, stl *m.SegmentTimeline p := path.Join(outDir, mPart) cnt, err = downloadAndCount(ctx, u, p, cnt, force) if err != nil { - log.Warn().Err(err).Msg("download file") + slog.Warn("download file", "error", err) } startTime += dur } @@ -207,7 +209,7 @@ func downloadSegmentNumber(ctx context.Context, stpl *m.SegmentTemplateType, tot startNr = *stpl.StartNumber } if stpl == nil { - log.Warn().Msg("segment duration not set") + slog.Warn("segment duration not set") return cnt } dur := *stpl.Duration @@ -223,7 +225,7 @@ func downloadSegmentNumber(ctx context.Context, stpl *m.SegmentTemplateType, tot p := path.Join(outDir, mPart) cnt, err = downloadAndCount(ctx, u, p, cnt, force) if err != nil && i < nrSegments { - log.Warn().Err(err).Msg("download file") + slog.Warn("download file", "error", err) } } return cnt @@ -232,7 +234,7 @@ func downloadSegmentNumber(ctx context.Context, stpl *m.SegmentTemplateType, tot func downloadAndCount(ctx context.Context, url, outPath string, cnt counts, force bool) (counts, error) { if fileExists(outPath) && !force { cnt.nrExisting++ - log.Info().Str("path", outPath).Str("url", url).Msg("file already exists. Skipping") + slog.Info("file already exists. Skipping", "path", outPath, "url", url) } else { err := downloadToFile(ctx, url, outPath) if err != nil { @@ -265,10 +267,10 @@ func replaceNumber(media string, nr uint32) string { func downloadToFile(ctx context.Context, url, outPath string) error { client := http.DefaultClient if fileExists(outPath) { - log.Info().Str("path", outPath).Msg("file exists") + slog.Info("file exists", "path", outPath) return nil } - log.Info().Str("url", url).Str("path", outPath).Msg("Downloading") + slog.Info("downloading", "url", url, "path", outPath) req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil) if err != nil { return err @@ -296,7 +298,7 @@ func downloadToFile(ctx context.Context, url, outPath string) error { if err != nil { return err } - log.Debug().Str("path", outPath).Msg("stored") + slog.Debug("stored", "path", outPath) return nil } diff --git a/cmd/dashfetcher/main.go b/cmd/dashfetcher/main.go index 4b7d28d..40108d9 100644 --- a/cmd/dashfetcher/main.go +++ b/cmd/dashfetcher/main.go @@ -6,11 +6,10 @@ package main import ( "fmt" + "log/slog" "os" "strings" - "github.com/rs/zerolog/log" - "github.com/Dash-Industry-Forum/livesim2/cmd/dashfetcher/app" "github.com/Dash-Industry-Forum/livesim2/internal" "github.com/Dash-Industry-Forum/livesim2/pkg/logging" @@ -35,9 +34,9 @@ func parseOptions() *app.Options { o := app.Options{} flag.StringVarP(&o.OutDir, "outdir", "o", ".", "output directory") flag.BoolVarP(&o.AutoOutDir, "auto", "a", false, "automatically add output directory parts from URL") - logFormatUsage := fmt.Sprintf("format and type of log: %v", logging.LogFormatsCommandLine) + logFormatUsage := fmt.Sprintf("format and type of log: %v", logging.LogFormats) flag.StringVarP(&o.LogFile, "logfile", "l", "", "log file [default stdout]") - flag.StringVarP(&o.LogFormat, "logformat", "", "consolepretty", logFormatUsage) + flag.StringVarP(&o.LogFormat, "logformat", "", logging.LogText, logFormatUsage) flag.StringVarP(&o.LogLevel, "loglevel", "", "info", "initial log level") flag.BoolVarP(&o.Version, "version", "v", false, "print version and date") longHelp := flag.Bool("help", false, "extended tool help") @@ -74,30 +73,34 @@ func parseOptions() *app.Options { func main() { o := parseOptions() - _, err := logging.InitZerolog(o.LogLevel, o.LogFormat) + err := logging.InitSlog(o.LogLevel, o.LogFormat) if err != nil { - log.Fatal().Err(err).Send() + slog.Error(err.Error()) + os.Exit(1) } if o.OutDir == "." { o.OutDir, err = os.Getwd() if err != nil { - log.Fatal().Err(err).Send() + slog.Error(err.Error()) + os.Exit(1) } } if o.AutoOutDir { o.OutDir, err = app.AutoDir(o.AssetURL, o.OutDir) if err != nil { - log.Fatal().Err(err).Send() + slog.Error(err.Error()) + os.Exit(1) } - log.Info().Str("output dir", o.OutDir).Msg("automatic output dir for MPD") + slog.Info("automatic output dir for MPD", "output dir", o.OutDir) } - log.Info().Str("version", internal.GetVersion()).Msg("starting") + slog.Info("starting", "version", internal.GetVersion()) err = app.Fetch(o) if err != nil { - log.Fatal().Err(err).Send() + slog.Error(err.Error()) + os.Exit(1) } } diff --git a/cmd/livesim2/app/asset.go b/cmd/livesim2/app/asset.go index 368bd64..3ac4ed0 100644 --- a/cmd/livesim2/app/asset.go +++ b/cmd/livesim2/app/asset.go @@ -11,6 +11,7 @@ import ( "fmt" "io" "io/fs" + "log/slog" "math" "os" "path" @@ -23,7 +24,6 @@ import ( m "github.com/Eyevinn/dash-mpd/mpd" "github.com/Eyevinn/mp4ff/bits" "github.com/Eyevinn/mp4ff/mp4" - "github.com/rs/zerolog/log" ) func newAssetMgr(vodFS fs.FS, repDataDir string, writeRepData bool) *assetMgr { @@ -73,7 +73,7 @@ func (am *assetMgr) discoverAssets() error { if path.Ext(p) == ".mpd" { err := am.loadAsset(p) if err != nil { - log.Warn().Err(err).Str("asset", p).Msg("Asset loading problem. Skipping") + slog.Warn("Asset loading problem. Skipping", "asset", p, "err", err.Error()) } } return nil @@ -88,11 +88,11 @@ func (am *assetMgr) discoverAssets() error { for aID, a := range am.assets { err := a.consolidateAsset() if err != nil { - log.Warn().Err(err).Str("asset", aID).Msg("Asset consolidation problem. Skipping") + slog.Warn("Asset consolidation problem. Skipping", "error", err.Error()) delete(am.assets, aID) // This deletion should be safe continue } - log.Info().Str("asset", a.AssetPath).Int("loopDurMS", a.LoopDurMS).Msg("Asset consolidated") + slog.Info("Asset consolidated", "asset", a.AssetPath, "loopDurMS", a.LoopDurMS) } return nil } @@ -142,7 +142,7 @@ func (am *assetMgr) loadAsset(mpdPath string) error { return fmt.Errorf("segmentTemplate on Representation level. Only supported on AdaptationSet level") } if _, ok := asset.Reps[rep.Id]; ok { - log.Debug().Str("rep", rep.Id).Str("asset", mpdPath).Msg("Representation already loaded") + slog.Debug("Representation already loaded", "rep", rep.Id, "asset", mpdPath) continue } r, err := am.loadRep(assetPath, mpd, as, rep) @@ -164,7 +164,7 @@ func (am *assetMgr) loadAsset(mpdPath string) error { } } } - log.Info().Str("mpdName", mpdPath).Msg("Asset MPD loaded") + slog.Info("asset MPD loaded", "asset", assetPath, "mpdName", mpdPath) return nil } @@ -177,11 +177,11 @@ func (am *assetMgr) loadRep(assetPath string, mpd *m.MPD, as *m.AdaptationSetTyp if !am.writeRepData { ok, err := rp.readFromJSON(am.vodFS, am.repDataDir, assetPath) if ok { - log.Info().Str("rep", rp.ID).Str("asset", assetPath).Msg("Representation loaded from JSON") + slog.Info("Representation loaded from JSON", "rep", rp.ID, "asset", assetPath) return &rp, err } } - log.Debug().Str("rep", rp.ID).Str("asset", assetPath).Msg("Loading full representation") + slog.Debug("Loading full representation", "rep", rp.ID, "asset", assetPath) st := as.SegmentTemplate if rep.SegmentTemplate != nil { st = rep.SegmentTemplate @@ -292,7 +292,7 @@ segLoop: } err = rp.writeToJSON(am.repDataDir, assetPath) if err == nil { - log.Info().Str("rep", rp.ID).Str("asset", assetPath).Msg("Representation data written to JSON file") + slog.Info("Representation data written to JSON file", "rep", rp.ID, "asset", assetPath) } return &rp, err } @@ -321,7 +321,7 @@ func (rp *RepData) readFromJSON(vodFS fs.FS, repDataDir, assetPath string) (bool if err != nil { return true, err } - log.Debug().Str("path", gzipPath).Msg("Read repData") + slog.Debug("Read repdata", "path", gzipPath) } if len(data) == 0 { _, err := os.Stat(repDataPath) @@ -330,7 +330,7 @@ func (rp *RepData) readFromJSON(vodFS fs.FS, repDataDir, assetPath string) (bool if err != nil { return true, err } - log.Debug().Str("path", repDataPath).Msg("Read repData") + slog.Debug("Read repdata", "path", repDataPath) } } if len(data) == 0 { @@ -395,7 +395,7 @@ func (rp *RepData) writeToJSON(repDataDir, assetPath string) error { if err != nil { return err } - log.Debug().Str("path", gzipPath).Msg("Wrote repData") + slog.Debug("Wrote repData", "path", gzipPath) return nil } @@ -607,7 +607,7 @@ func (a *asset) consolidateAsset() error { } repDurMS := 1000 * rep.duration() / rep.MediaTimescale if repDurMS != a.LoopDurMS { - log.Info().Str("rep", rep.ID).Str("asset", a.AssetPath).Msg("rep duration differs from loop duration") + slog.Info("Rep duration differs from loop duration", "rep", rep.ID, "asset", a.AssetPath) } } return nil diff --git a/cmd/livesim2/app/config.go b/cmd/livesim2/app/config.go index d676afa..7a6daa0 100644 --- a/cmd/livesim2/app/config.go +++ b/cmd/livesim2/app/config.go @@ -62,8 +62,8 @@ type ServerConfig struct { } var DefaultConfig = ServerConfig{ - LogFormat: "consolepretty", - LogLevel: "info", + LogFormat: "text", + LogLevel: "INFO", Port: 8888, LiveWindowS: 300, TimeoutS: 60, diff --git a/cmd/livesim2/app/handler_assets.go b/cmd/livesim2/app/handler_assets.go index f624480..1e6c7e5 100644 --- a/cmd/livesim2/app/handler_assets.go +++ b/cmd/livesim2/app/handler_assets.go @@ -6,12 +6,11 @@ package app import ( "fmt" + "log/slog" "net/http" "net/url" "sort" "strings" - - "github.com/rs/zerolog/log" ) type assetsInfo struct { @@ -45,7 +44,7 @@ func (s *Server) assetsHandlerFunc(w http.ResponseWriter, r *http.Request) { fh := fullHost(s.Cfg.Host, r) playURL, err := createPlayURL(fh, s.Cfg.PlayURL) if err != nil { - log.Err(err).Msg("cannot create playurl") + slog.Error("cannot create playurl") http.Error(w, err.Error(), http.StatusInternalServerError) return } diff --git a/cmd/livesim2/app/handler_index_test.go b/cmd/livesim2/app/handler_index_test.go index 0815f8d..b842e18 100644 --- a/cmd/livesim2/app/handler_index_test.go +++ b/cmd/livesim2/app/handler_index_test.go @@ -23,7 +23,7 @@ func TestIndexPageWithHost(t *testing.T) { LogFormat: logging.LogDiscard, Host: "https://example.com/subfolder", } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) @@ -41,7 +41,7 @@ func TestIndexPageWithoutHost(t *testing.T) { TimeoutS: 0, LogFormat: logging.LogDiscard, } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) diff --git a/cmd/livesim2/app/handler_livesim.go b/cmd/livesim2/app/handler_livesim.go index dbcdabf..1c8a758 100644 --- a/cmd/livesim2/app/handler_livesim.go +++ b/cmd/livesim2/app/handler_livesim.go @@ -10,6 +10,7 @@ import ( "errors" "fmt" "io/fs" + "log/slog" "net/http" "net/url" "path" @@ -20,19 +21,18 @@ import ( "time" "github.com/Dash-Industry-Forum/livesim2/pkg/logging" - "github.com/rs/zerolog" ) // livesimHandlerFunc handles mpd and segment requests. // ?nowMS=... can be used to set the current time for testing. func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { - log := logging.SubLoggerWithRequestIDAndTopic(r, "livesim") + log := logging.SubLoggerWithRequestID(slog.Default(), r) uPath := r.URL.Path ext := filepath.Ext(uPath) u, err := url.Parse(uPath) if err != nil { msg := "URL parser" - log.Error().Err(err).Msg(msg) + log.Error(msg) http.Error(w, msg, http.StatusInternalServerError) return } @@ -53,7 +53,7 @@ func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { cfg, err := processURLCfg(u.String(), nowMS) if err != nil { msg := "processURL error" - log.Error().Err(err).Msg(msg) + log.Error(msg, "err", err) http.Error(w, msg, http.StatusInternalServerError) return } @@ -66,7 +66,7 @@ func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { } contentPart := cfg.URLContentPart() - log.Debug().Str("url", contentPart).Msg("requested content") + log.Debug("requested content", "url", contentPart) a, ok := s.assetMgr.findAsset(contentPart) if !ok { http.Error(w, "unknown asset", http.StatusNotFound) @@ -85,7 +85,7 @@ func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { if err != nil { // TODO. Add more granular errors like 404 not found msg := fmt.Sprintf("liveMPD: %s", err) - log.Error().Err(err).Msg(msg) + log.Error(msg) http.Error(w, msg, http.StatusInternalServerError) return } @@ -104,7 +104,7 @@ func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { http.Error(w, "Gone", http.StatusGone) default: msg := "writeSegment" - log.Error().Err(err).Msg(msg) + log.Error(msg) http.Error(w, msg, http.StatusInternalServerError) return } @@ -115,7 +115,7 @@ func (s *Server) livesimHandlerFunc(w http.ResponseWriter, r *http.Request) { } } -func writeLiveMPD(log *zerolog.Logger, w http.ResponseWriter, cfg *ResponseConfig, a *asset, mpdName string, nowMS int) error { +func writeLiveMPD(log *slog.Logger, w http.ResponseWriter, cfg *ResponseConfig, a *asset, mpdName string, nowMS int) error { work := make([]byte, 0, 1024) buf := bytes.NewBuffer(work) lMPD, err := LiveMPD(a, mpdName, cfg, nowMS) @@ -130,17 +130,19 @@ func writeLiveMPD(log *zerolog.Logger, w http.ResponseWriter, cfg *ResponseConfi w.Header().Set("Content-Type", "application/dash+xml") n, err := w.Write(buf.Bytes()) if err != nil { - log.Error().Err(err).Msg("writing response") + log.Error("writing response") return err } if n != size { - log.Error().Int("size", size).Int("nr written", n).Msg("could not write all bytes") + log.Error("could not write all bytes", + "size", size, + "nr written", n) return err } return nil } -func writeSegment(ctx context.Context, w http.ResponseWriter, log *zerolog.Logger, cfg *ResponseConfig, vodFS fs.FS, a *asset, +func writeSegment(ctx context.Context, w http.ResponseWriter, log *slog.Logger, cfg *ResponseConfig, vodFS fs.FS, a *asset, segmentPart string, nowMS int, tt *template.Template) error { // First check if init segment and return isInitSegment, err := writeInitSegment(w, cfg, vodFS, a, segmentPart) diff --git a/cmd/livesim2/app/handler_livesim_test.go b/cmd/livesim2/app/handler_livesim_test.go index 4bdca0c..ff68d43 100644 --- a/cmd/livesim2/app/handler_livesim_test.go +++ b/cmd/livesim2/app/handler_livesim_test.go @@ -21,7 +21,7 @@ func TestParamToMPD(t *testing.T) { TimeoutS: 0, LogFormat: logging.LogDiscard, } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) @@ -86,7 +86,7 @@ func TestFetches(t *testing.T) { TimeoutS: 0, LogFormat: logging.LogDiscard, } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) diff --git a/cmd/livesim2/app/handler_urlgen.go b/cmd/livesim2/app/handler_urlgen.go index 018e383..d1fe645 100644 --- a/cmd/livesim2/app/handler_urlgen.go +++ b/cmd/livesim2/app/handler_urlgen.go @@ -6,12 +6,11 @@ package app import ( "fmt" + "log/slog" "net/http" "sort" "strconv" "strings" - - "github.com/rs/zerolog/log" ) // urlGenHandlerFunc returns page for generating URLs @@ -26,7 +25,7 @@ func (s *Server) urlGenHandlerFunc(w http.ResponseWriter, r *http.Request) { fh := fullHost(s.Cfg.Host, r) playURL, err := createPlayURL(fh, s.Cfg.PlayURL) if err != nil { - log.Err(err).Msg("cannot create playurl") + slog.Error("cannot create playurl", "error", err) http.Error(w, err.Error(), http.StatusInternalServerError) return } diff --git a/cmd/livesim2/app/ipreqlimit.go b/cmd/livesim2/app/ipreqlimit.go index c60d989..830ead9 100644 --- a/cmd/livesim2/app/ipreqlimit.go +++ b/cmd/livesim2/app/ipreqlimit.go @@ -7,13 +7,12 @@ package app import ( "encoding/json" "fmt" + "log/slog" "net" "net/http" "os" "sync" "time" - - "github.com/rs/zerolog/log" ) // IPRequestLimiter limits the number of requests per interval @@ -100,17 +99,19 @@ func (il *IPRequestLimiter) EndTime() time.Time { func (il *IPRequestLimiter) dump() { payload, err := json.Marshal(il) if err != nil { - log.Error().Err(err).Msg("could not marshal IPRequestLimiter") + slog.Error("could not marshal IPRequestLimiter", "error", err.Error()) return } f, err := os.OpenFile(il.logFile, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600) if err != nil { - log.Error().Err(err).Msg("could not open IPRequestLimiter log file") + slog.Error("could not open IPRequestLimiter log file", "error", err.Error()) + } defer f.Close() _, err = f.Write(payload) if err != nil { - log.Error().Err(err).Msg("could not write to IPRequestLimiter log file") + slog.Error("could not write to IPRequestLimiter log file", "error", err.Error()) + } } diff --git a/cmd/livesim2/app/livesegment.go b/cmd/livesim2/app/livesegment.go index 5dc94d8..2219980 100644 --- a/cmd/livesim2/app/livesegment.go +++ b/cmd/livesim2/app/livesegment.go @@ -8,6 +8,7 @@ import ( "context" "fmt" "io/fs" + "log/slog" "math" "net/http" "path" @@ -20,8 +21,6 @@ import ( "github.com/Dash-Industry-Forum/livesim2/pkg/scte35" "github.com/Eyevinn/mp4ff/bits" "github.com/Eyevinn/mp4ff/mp4" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" ) // genLiveSegment generates a live segment from one or more VoD segments following cfg and media type @@ -72,7 +71,7 @@ func genLiveSegment(vodFS fs.FS, a *asset, cfg *ResponseConfig, segmentPart stri } if emsg != nil { seg.Fragments[0].AddEmsg(emsg) - log.Debug().Str("asset", a.AssetPath).Str("segment", segmentPart).Msg("added SCTE-35 emsg message") + slog.Debug("added SCTE-35 emsg message", "asset", a.AssetPath, "segment", segmentPart) } } outSeg.seg = seg @@ -272,7 +271,7 @@ func writeInitSegment(w http.ResponseWriter, cfg *ResponseConfig, vodFS fs.FS, a w.Header().Set("Content-Type", rep.SegmentType()) _, err := w.Write(rep.initBytes) if err != nil { - log.Error().Err(err).Msg("writing response") + slog.Error("writing response", "error", err) return false, err } return true, nil @@ -296,7 +295,7 @@ func writeLiveSegment(w http.ResponseWriter, cfg *ResponseConfig, vodFS fs.FS, a sw := bits.NewFixedSliceWriter(int(outSeg.seg.Size())) err = outSeg.seg.EncodeSW(sw) if err != nil { - log.Error().Err(err).Msg("write live segment response") + slog.Error("write live segment response", "error", err) return err } data = sw.Bytes() @@ -307,7 +306,7 @@ func writeLiveSegment(w http.ResponseWriter, cfg *ResponseConfig, vodFS fs.FS, a w.Header().Set("Content-Type", outSeg.meta.rep.SegmentType()) _, err = w.Write(data) if err != nil { - log.Error().Err(err).Msg("write live segment response") + slog.Error("write live segment response", "error", err) return err } return nil @@ -424,7 +423,7 @@ func createAudioSegment(vodFS fs.FS, a *asset, cfg *ResponseConfig, segmentPart // // nowMS servers as reference for the current time and can be set to any value. Media time will // be incremented with respect to nowMS. -func writeChunkedSegment(ctx context.Context, w http.ResponseWriter, log *zerolog.Logger, cfg *ResponseConfig, +func writeChunkedSegment(ctx context.Context, w http.ResponseWriter, log *slog.Logger, cfg *ResponseConfig, vodFS fs.FS, a *asset, segmentPart string, nowMS int) error { so, err := genLiveSegment(vodFS, a, cfg, segmentPart, nowMS) diff --git a/cmd/livesim2/app/livesegment_test.go b/cmd/livesim2/app/livesegment_test.go index f428a17..10f49a4 100644 --- a/cmd/livesim2/app/livesegment_test.go +++ b/cmd/livesim2/app/livesegment_test.go @@ -7,6 +7,7 @@ package app import ( "context" "fmt" + "log/slog" "math" "net/http" "net/http/httptest" @@ -220,7 +221,7 @@ func TestWriteChunkedSegment(t *testing.T) { cfg := NewResponseConfig() cfg.AvailabilityTimeCompleteFlag = false cfg.AvailabilityTimeOffsetS = 7.0 - log, err := logging.InitZerolog("debug", "discard") + err = logging.InitSlog("debug", "discard") require.NoError(t, err) cases := []struct { @@ -243,7 +244,7 @@ func TestWriteChunkedSegment(t *testing.T) { rr := httptest.NewRecorder() segmentPart := strings.Replace(tc.media, "$NrOrTime$", "10", 1) mediaTime := 80 * tc.mediaTimescale - err := writeChunkedSegment(context.Background(), rr, log, cfg, vodFS, asset, segmentPart, nowMS) + err := writeChunkedSegment(context.Background(), rr, slog.Default(), cfg, vodFS, asset, segmentPart, nowMS) require.NoError(t, err) seg := rr.Body.Bytes() sr := bits.NewFixedSliceReader(seg) @@ -360,7 +361,7 @@ func TestStartNumber(t *testing.T) { am := newAssetMgr(vodFS, "", false) err := am.discoverAssets() require.NoError(t, err) - _, err = logging.InitZerolog("debug", "discard") + err = logging.InitSlog("debug", "discard") require.NoError(t, err) cases := []struct { diff --git a/cmd/livesim2/app/server.go b/cmd/livesim2/app/server.go index a7aa619..d6be060 100644 --- a/cmd/livesim2/app/server.go +++ b/cmd/livesim2/app/server.go @@ -7,13 +7,12 @@ package app import ( "encoding/json" "fmt" + "log/slog" "net/http" "strconv" "github.com/go-chi/chi/v5" - "github.com/Dash-Industry-Forum/livesim2/pkg/logging" - htmpl "html/template" ttmpl "text/template" @@ -24,7 +23,6 @@ type Server struct { Router *chi.Mux LiveRouter *chi.Mux VodRouter *chi.Mux - logger *logging.Logger Cfg *ServerConfig assetMgr *assetMgr textTemplates *ttmpl.Template @@ -36,10 +34,6 @@ func (s *Server) healthzHandlerFunc(w http.ResponseWriter, r *http.Request) { s.jsonResponse(w, true, http.StatusOK) } -func (s *Server) GetLogger() *logging.Logger { - return s.logger -} - // jsonResponse marshals message and give response with code // // Don't add any more content after this since Content-Length is set @@ -47,16 +41,14 @@ func (s *Server) jsonResponse(w http.ResponseWriter, message interface{}, code i raw, err := json.Marshal(message) if err != nil { http.Error(w, fmt.Sprintf("{message: \"%s\"}", err), http.StatusInternalServerError) - s.logger.Error().Msg(err.Error()) + slog.Error(err.Error()) } w.Header().Set("Content-Type", "application/json") w.WriteHeader(code) w.Header().Set("Content-Length", strconv.Itoa(len(raw))) _, err = w.Write(raw) if err != nil { - s.logger.Error(). - Str("error", err.Error()). - Msg("Could not write HTTP response") + slog.Error("could not write HTTP response", "err", err) } } @@ -66,12 +58,12 @@ func (s *Server) compileTemplates() error { if err != nil { return fmt.Errorf("compileTextTemplates: %w", err) } - s.logger.Debug().Str("tmpl", s.textTemplates.DefinedTemplates()).Msg("text templates") + slog.Debug("text templates", "defined", s.textTemplates.DefinedTemplates()) s.htmlTemplates, err = compileHTMLTemplates(content, "templates") if err != nil { return fmt.Errorf("compileHTMLTemplates: %w", err) } - s.logger.Debug().Str("tmpl", s.htmlTemplates.DefinedTemplates()).Msg("html templates") + slog.Debug("html templates", "defined", s.htmlTemplates.DefinedTemplates()) return nil } diff --git a/cmd/livesim2/app/server_test.go b/cmd/livesim2/app/server_test.go index 26e60c5..a234c55 100644 --- a/cmd/livesim2/app/server_test.go +++ b/cmd/livesim2/app/server_test.go @@ -23,7 +23,7 @@ func TestServer(t *testing.T) { cfg, err := app.LoadConfig(args, ".") assert.NoError(t, err) - _, err = logging.InitZerolog(cfg.LogLevel, logging.LogDiscard) + err = logging.InitSlog(cfg.LogLevel, logging.LogDiscard) assert.NoError(t, err) server, err := app.SetupServer(context.Background(), cfg) diff --git a/cmd/livesim2/app/start.go b/cmd/livesim2/app/start.go index 6283f20..72e6a60 100644 --- a/cmd/livesim2/app/start.go +++ b/cmd/livesim2/app/start.go @@ -7,6 +7,7 @@ package app import ( "context" "fmt" + "log/slog" "os" "time" @@ -22,11 +23,11 @@ import ( func SetupServer(ctx context.Context, cfg *ServerConfig) (*Server, error) { var err error - logger := logging.GetGlobalLogger() + logger := slog.Default() r := chi.NewRouter() r.Use(middleware.RequestID) - r.Use(logging.ZerologMiddleware(logger)) + r.Use(logging.SlogMiddleWare(logger)) r.Use(middleware.Recoverer) r.Use(addVersionAndCORSHeaders) prometheusMiddleWare := NewPrometheusMiddleware() @@ -64,7 +65,6 @@ func SetupServer(ctx context.Context, cfg *ServerConfig) (*Server, error) { Router: r, LiveRouter: l, VodRouter: v, - logger: logger, Cfg: cfg, assetMgr: newAssetMgr(vodFS, cfg.RepDataRoot, cfg.WriteRepData), reqLimiter: reqLimiter, @@ -87,15 +87,17 @@ func SetupServer(ctx context.Context, cfg *ServerConfig) (*Server, error) { } elapsedSeconds := fmt.Sprintf("%.3fs", time.Since(start).Seconds()) - logger.Info().Int("count", len(server.assetMgr.assets)).Str("elapsed", elapsedSeconds).Msg("VoD assets found") + logger.Info("Vod asset found", + "count", len(server.assetMgr.assets), + "elapsed seconds", elapsedSeconds) for name := range server.assetMgr.assets { a := server.assetMgr.assets[name] for mpdName := range a.MPDs { - logger.Info().Str("assetPath", name).Str("mpdName", mpdName).Msg("Available MPD") + logger.Info("Available MPD", "assetPath", name, "mpdName", mpdName) } } - logger.Info().Str("version", internal.GetVersion()).Int("port", cfg.Port).Msg("livesim2 starting") + logger.Info("livesim2 starting", "version", internal.GetVersion(), "port", cfg.Port) return &server, nil } diff --git a/cmd/livesim2/app/timesubs.go b/cmd/livesim2/app/timesubs.go index 93c340c..b0ceca4 100644 --- a/cmd/livesim2/app/timesubs.go +++ b/cmd/livesim2/app/timesubs.go @@ -7,6 +7,7 @@ package app import ( "bytes" "fmt" + "log/slog" "math" "net/http" "strconv" @@ -15,7 +16,6 @@ import ( "time" "github.com/Eyevinn/mp4ff/mp4" - "github.com/rs/zerolog/log" ) const ( @@ -85,7 +85,7 @@ func writeTimeSubsInitSegment(w http.ResponseWriter, cfg *ResponseConfig, a *ass w.Header().Set("Content-Length", strconv.Itoa(int(init.Size()))) err := init.Encode(w) if err != nil { - log.Error().Err(err).Msg("write init response") + slog.Error("write init response", "error", err) return true, err } return true, nil @@ -174,7 +174,7 @@ func writeTimeSubsMediaSegment(w http.ResponseWriter, cfg *ResponseConfig, a *as return true, fmt.Errorf("getRefSegMeta: %w", err) } - log.Debug().Uint32("nr", refSegMeta.newNr).Msg("segMeta") + slog.Debug("segMeta", "nr", refSegMeta.newNr) baseMediaDecodeTime := rep2SubsTime(refSegMeta.newTime, int(refSegMeta.timescale)) dur := uint32(rep2SubsTime(uint64(refSegMeta.newDur), int(refSegMeta.timescale))) @@ -195,7 +195,7 @@ func writeTimeSubsMediaSegment(w http.ResponseWriter, cfg *ResponseConfig, a *as w.Header().Set("Content-Length", strconv.Itoa(int(mediaSeg.Size()))) err = mediaSeg.Encode(w) if err != nil { - log.Error().Err(err).Msg("write media segment response") + slog.Error("write media segment response", "error", err) return true, fmt.Errorf("mediaSeg: %w", err) } return true, nil diff --git a/cmd/livesim2/app/timesubs_test.go b/cmd/livesim2/app/timesubs_test.go index 231ade0..b9491ea 100644 --- a/cmd/livesim2/app/timesubs_test.go +++ b/cmd/livesim2/app/timesubs_test.go @@ -252,7 +252,7 @@ func TestTimeSubsInitSegment(t *testing.T) { TimeoutS: 0, LogFormat: logging.LogDiscard, } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) @@ -343,7 +343,7 @@ func TestTimeSubsMediaSegment(t *testing.T) { TimeoutS: 0, LogFormat: logging.LogDiscard, } - _, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err := logging.InitSlog(cfg.LogLevel, cfg.LogFormat) require.NoError(t, err) server, err := SetupServer(context.Background(), &cfg) require.NoError(t, err) diff --git a/cmd/livesim2/main.go b/cmd/livesim2/main.go index a3002eb..b0f8af7 100644 --- a/cmd/livesim2/main.go +++ b/cmd/livesim2/main.go @@ -7,6 +7,7 @@ package main import ( "context" "fmt" + "log/slog" "net/http" "os" "os/signal" @@ -34,9 +35,10 @@ func run() (exitCode int) { os.Exit(1) } - logger, err := logging.InitZerolog(cfg.LogLevel, cfg.LogFormat) + err = logging.InitSlog(cfg.LogLevel, cfg.LogFormat) if err != nil { - logger.Fatal().Err(err).Send() + _, _ = fmt.Fprintf(os.Stderr, "Error initializing logging: %s\n", err.Error()) + os.Exit(1) } stopSignal := make(chan os.Signal, 1) @@ -79,14 +81,14 @@ func run() (exitCode int) { err = http.ListenAndServe(fmt.Sprintf(":%d", server.Cfg.Port), server.Router) } if err != nil && err != http.ErrServerClosed { - logger.Error().Err(err).Msg("") + slog.Default().Error(err.Error()) exitCode = 1 startIssue <- struct{}{} } }() <-stopServer // Wait here for stop signal - logger.Info().Msg("Server stopped") + slog.Default().Info("Server stopped") return exitCode } diff --git a/go.mod b/go.mod index b528605..9c041ca 100644 --- a/go.mod +++ b/go.mod @@ -1,16 +1,18 @@ module github.com/Dash-Industry-Forum/livesim2 -go 1.19 +go 1.21.0 + +toolchain go1.21.1 require ( github.com/Comcast/gots v1.0.4 github.com/Eyevinn/dash-mpd v0.10.0 github.com/Eyevinn/mp4ff v0.39.0 github.com/caddyserver/certmagic v0.19.2 + github.com/dusted-go/logging v1.1.1 github.com/go-chi/chi/v5 v5.0.10 github.com/knadh/koanf v1.5.0 github.com/prometheus/client_golang v1.17.0 - github.com/rs/zerolog v1.31.0 github.com/spf13/pflag v1.0.5 github.com/stretchr/testify v1.8.4 @@ -20,15 +22,12 @@ require ( github.com/barkimedes/go-deepcopy v0.0.0-20220514131651-17c30cfc62df // indirect github.com/beorn7/perks v1.0.1 // indirect github.com/cespare/xxhash/v2 v2.2.0 // indirect - github.com/coreos/go-systemd/v22 v22.5.0 // indirect github.com/davecgh/go-spew v1.1.1 // indirect github.com/fatih/structs v1.1.0 // indirect github.com/fsnotify/fsnotify v1.6.0 // indirect github.com/golang/protobuf v1.5.3 // indirect github.com/klauspost/cpuid/v2 v2.2.5 // indirect github.com/libdns/libdns v0.2.1 // indirect - github.com/mattn/go-colorable v0.1.13 // indirect - github.com/mattn/go-isatty v0.0.19 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect github.com/mholt/acmez v1.2.0 // indirect github.com/miekg/dns v1.1.56 // indirect diff --git a/go.sum b/go.sum index 748486a..a0657e2 100644 --- a/go.sum +++ b/go.sum @@ -1,4 +1,5 @@ aqwari.net/xml v0.0.0-20210331023308-d9421b293817 h1:+3Rh5EaTzNLnzWx3/uy/mAaH/dGI7svJ6e0oOIDcPuE= +aqwari.net/xml v0.0.0-20210331023308-d9421b293817/go.mod h1:c7kkWzc7HS/t8Q2DcVY8P2d1dyWNEhEVT5pL0ZHO11c= cloud.google.com/go v0.26.0/go.mod h1:aQUYkXzVsufM+DwF1aE+0xfcU+56JwCaLick0ClmMTw= cloud.google.com/go v0.34.0/go.mod h1:aQUYkXzVsufM+DwF1aE+0xfcU+56JwCaLick0ClmMTw= github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU= @@ -6,8 +7,6 @@ github.com/Comcast/gots v1.0.4 h1:OBxaTTM2kEjZZ9QTYsEVIUkaY3hAmy4spJOjpcgJk+A= github.com/Comcast/gots v1.0.4/go.mod h1:/EieJXsI8HTyAAGPoardzq/OY+jL+RiyG+sq0cZgkyk= github.com/Eyevinn/dash-mpd v0.10.0 h1:Pdaw41SDaytYkugct9XMDYfhVigDfGmDjJZtzLksXZs= github.com/Eyevinn/dash-mpd v0.10.0/go.mod h1:CuBY8vahrq4cBrEflTU/ujCRlyGjw5ER2us+I2+PZzI= -github.com/Eyevinn/mp4ff v0.38.2-0.20231008210406-65ee06764473 h1:N/NPEMvB3W1u0afUNT7hh32Hns77IMYUIkF3xkh3PYM= -github.com/Eyevinn/mp4ff v0.38.2-0.20231008210406-65ee06764473/go.mod h1:w/6GSa5ghZ1VavzJK6McQ2/flx8mKtcrKDr11SsEweA= github.com/Eyevinn/mp4ff v0.39.0 h1:WV2Omq57y1BvcVPayjyuiIK8/pF5Tb/H/cgPY+wFZMQ= github.com/Eyevinn/mp4ff v0.39.0/go.mod h1:w/6GSa5ghZ1VavzJK6McQ2/flx8mKtcrKDr11SsEweA= github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= @@ -48,11 +47,11 @@ github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGX github.com/cncf/udpa/go v0.0.0-20201120205902-5459f2c99403/go.mod h1:WmhPx2Nbnhtbo57+VJT5O0JRkEi1Wbu0z5j0R8u5Hbk= github.com/coreos/go-semver v0.3.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk= github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= -github.com/coreos/go-systemd/v22 v22.5.0 h1:RrqgGjYQKalulkV8NGVIfkXQf6YYmOyiJKk8iXXhfZs= -github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/dusted-go/logging v1.1.1 h1:x1aSyarDh2iq7MIhCZkjbepsZD9FmAURK93jRFm2Oco= +github.com/dusted-go/logging v1.1.1/go.mod h1:Lim3Rk6x2MYwpvPZ6XzPk6ZeX4Wgz9lVOptrL7ngr5w= github.com/dustin/go-humanize v1.0.0/go.mod h1:HtrtbFcZ19U5GC7JDqmcUSB87Iq5E25KnS6fMYU6eOk= github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= github.com/envoyproxy/go-control-plane v0.9.1-0.20191026205805-5f8ba28d4473/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= @@ -113,6 +112,7 @@ github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/ github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.7/go.mod h1:n+brtR0CgQNWTVd5ZUFpTBC8YFBDLK/h/bpaJ8/DtOE= github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= +github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= github.com/google/uuid v1.1.2/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0/go.mod h1:8NvIoxWQoOIhqOTXgfV/d3M/q6VIi02HzZEHgUlZvzk= @@ -176,24 +176,21 @@ github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFB github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= +github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= +github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/libdns/libdns v0.2.1 h1:Wu59T7wSHRgtA0cfxC+n1c/e+O3upJGWytknkmFEDis= github.com/libdns/libdns v0.2.1/go.mod h1:yQCXzk1lEZmmCPa857bnk4TsOiqYasqpyOEeSObbb40= github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU= github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= github.com/mattn/go-colorable v0.1.6/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= -github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= -github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4= github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84= github.com/mattn/go-isatty v0.0.11/go.mod h1:PhnuNfih5lzO57/f3n+odYbM4JtupLOxQOAqxQCu2WE= github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= -github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= -github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA= -github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0= github.com/matttproud/golang_protobuf_extensions v1.0.4 h1:mmDVorXM7PCGKw94cs5zkfA9PSy5pEvNWRP0ET0TIVo= github.com/matttproud/golang_protobuf_extensions v1.0.4/go.mod h1:BSXmuO+STAnVfrANrmjBb36TMTDstsz7MSK+HVaYKv4= @@ -265,9 +262,7 @@ github.com/prometheus/procfs v0.12.0/go.mod h1:pcuDEFsWDnvcgNzo4EEweacyhjeA9Zk3c github.com/rhnvrm/simples3 v0.6.1/go.mod h1:Y+3vYm2V7Y4VijFoJHHTrja6OgPrJ2cBti8dPGkC3sA= github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ= github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A= -github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= +github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= github.com/ryanuber/columnize v2.1.0+incompatible/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts= github.com/ryanuber/go-glob v1.0.0/go.mod h1:807d1WSdnB0XRJzKNil9Om6lcp/3a0v4qIHxIXzX/Yc= @@ -300,6 +295,7 @@ go.etcd.io/etcd/client/pkg/v3 v3.5.4/go.mod h1:IJHfcCEKxYu1Os13ZdwCwIUTUVGYTSAM3 go.etcd.io/etcd/client/v3 v3.5.4/go.mod h1:ZaRkVgBZC+L+dLCjTcF1hRXpgZXQPOvnA/Ak/gq3kiY= go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc= go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk= +go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo= go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU= go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0= go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= @@ -356,6 +352,7 @@ golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.4.0 h1:zxkM55ReGkDlKSM+Fu41A+zmbZuaPVbGMzvvdUPznYQ= +golang.org/x/sync v0.4.0/go.mod h1:FU7BRWz2tNW+3quACPkgCx/L+uEAv1htQ0V83Z9Rj+Y= golang.org/x/sys v0.0.0-20180823144017-11551d06cbcc/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= @@ -386,11 +383,8 @@ golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20210403161142-5e06dd20ab57/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210603081109-ebe580a85c40/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.13.0 h1:Af8nKPmuFypiUBjVoU9V20FiaFXOcuZI21p0ycVYYGE= golang.org/x/sys v0.13.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= @@ -454,6 +448,7 @@ gopkg.in/asn1-ber.v1 v1.0.0-20181015200546-f715ec2f112d/go.mod h1:cuepJuh7vyXfUy gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= gopkg.in/square/go-jose.v2 v2.3.1/go.mod h1:M9dMgbHiYLoDGQrXy7OpJDJWiKiU//h+vD76mk0e1AI= gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= diff --git a/pkg/logging/http_handler.go b/pkg/logging/http_handler.go index 4747e5c..d588c90 100644 --- a/pkg/logging/http_handler.go +++ b/pkg/logging/http_handler.go @@ -20,15 +20,16 @@ var LogRoutes = [2]Route{ {"POST", "/loglevel", LogLevelSet}, } -// LogLevelGet - Handle loglevel GET request +// LogLevelGet handles loglevel GET request func LogLevelGet(w http.ResponseWriter, r *http.Request) { - currentLevel := GetLogLevel() + currentLevel := LogLevel() fmt.Fprintln(w, currentLevel) } -// LogLevelSet - Handle loglevel POST request +// LogLevelSet sets the loglevel from a posted form +// Can be triggered like curl -F level=debug /loglevel func LogLevelSet(w http.ResponseWriter, r *http.Request) { - currentLevel := GetLogLevel() + currentLevel := LogLevel() err := r.ParseMultipartForm(128) if err != nil { http.Error(w, "Incorrect form data", http.StatusBadRequest) @@ -41,5 +42,5 @@ func LogLevelSet(w http.ResponseWriter, r *http.Request) { http.Error(w, msg, http.StatusBadRequest) return } - fmt.Fprintf(w, "%q → %q\n", currentLevel, newLevel) + fmt.Fprintf(w, "%q → %q\n", currentLevel, LogLevel()) } diff --git a/pkg/logging/http_handler_test.go b/pkg/logging/http_handler_test.go index 288094d..71ccab6 100644 --- a/pkg/logging/http_handler_test.go +++ b/pkg/logging/http_handler_test.go @@ -52,7 +52,7 @@ func postLoglevel(t *testing.T, server *httptest.Server, level string) (*http.Re // TestHandleLoglevel - Test of log level handler func TestHandleLoglevelX(t *testing.T) { // Initialize logging to debug - _, err := InitZerolog("debug", LogJSON) + err := InitSlog("DEBUG", LogJSON) require.NoError(t, err) // Create test server with loglevel routes @@ -64,18 +64,18 @@ func TestHandleLoglevelX(t *testing.T) { defer ts.Close() // Verify initial log level - verifyLogLevel(t, ts, "debug\n") + verifyLogLevel(t, ts, "DEBUG\n") // Set log level to info - resp, _ := postLoglevel(t, ts, "info") + resp, _ := postLoglevel(t, ts, "INFO") require.Equal(t, http.StatusOK, resp.StatusCode) // Verify new log level - verifyLogLevel(t, ts, "info\n") + verifyLogLevel(t, ts, "INFO\n") // Set invalid log level resp, _ = postLoglevel(t, ts, "banana") require.Equal(t, http.StatusBadRequest, resp.StatusCode) // Log level should still be info - verifyLogLevel(t, ts, "info\n") + verifyLogLevel(t, ts, "INFO\n") } diff --git a/pkg/logging/init.go b/pkg/logging/init.go index d37f753..a97e2a9 100644 --- a/pkg/logging/init.go +++ b/pkg/logging/init.go @@ -1,49 +1,42 @@ -//go:build !windows -// +build !windows - +// Copyright 2023, DASH-Industry Forum. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE.md file. package logging import ( - "errors" "fmt" "io" + "log/slog" "os" - "time" - "github.com/rs/zerolog" - "github.com/rs/zerolog/journald" - "github.com/rs/zerolog/log" + "github.com/dusted-go/logging/prettylog" ) -// InitZerolog initializes the global zerolog logger. +// InitSlog initializes the global slog logger. // // level and logLevel determine where the logs go and what format is used. -func InitZerolog(level string, logFormat string) (*Logger, error) { +func InitSlog(level string, logFormat string) error { - if !isValidLogFormat(logFormat) { - msg := fmt.Sprintf("Unknown log format: %q", logFormat) - err := errors.New(msg) - return nil, err - } + var logger *slog.Logger + logLevel = new(slog.LevelVar) switch logFormat { + case LogText: + logger = slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel})) case LogJSON: - log.Logger = zerolog.New(os.Stdout).With().Timestamp().Logger() - case LogConsolePretty: - log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}). - With().Timestamp().Logger() - case LogJournald: - log.Logger = zerolog.New(journald.NewJournalDWriter()) + logger = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel})) + case LogPretty: + f := func(groups []string, a slog.Attr) slog.Attr { return a } + prettyHandler := prettylog.NewHandler(&slog.HandlerOptions{ + Level: logLevel, + AddSource: false, + ReplaceAttr: f}) + logger = slog.New(prettyHandler) case LogDiscard: - log.Logger = zerolog.New(io.Discard) + logger = slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: logLevel})) default: - return nil, fmt.Errorf("logFormat %q not known", logFormat) + return fmt.Errorf("logFormat %q not known", logFormat) } - - err := SetLogLevel(level) - if err != nil { - return nil, err - } - - return &log.Logger, nil + slog.SetDefault(logger) + return SetLogLevel(level) } diff --git a/pkg/logging/init_windows.go b/pkg/logging/init_windows.go deleted file mode 100644 index 7a9be39..0000000 --- a/pkg/logging/init_windows.go +++ /dev/null @@ -1,48 +0,0 @@ -//go:build windows -// +build windows - -package logging - -import ( - "errors" - "fmt" - "io" - "os" - "time" - - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" -) - -// InitZerolog initializes the global zerolog logger. -// -// level and logLevel determine where the logs go and what format is used. -func InitZerolog(level string, logFormat string) (*Logger, error) { - - if !isValidLogFormat(logFormat) { - msg := fmt.Sprintf("Unknown log format: %q", logFormat) - err := errors.New(msg) - return nil, err - } - - switch logFormat { - case LogJSON: - log.Logger = zerolog.New(os.Stdout).With().Timestamp().Logger() - case LogConsolePretty: - log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}). - With().Timestamp().Logger() - case LogJournald: - return nil, fmt.Errorf("journald logging not supported on Windows") - case LogDiscard: - log.Logger = zerolog.New(io.Discard) - default: - return nil, fmt.Errorf("logFormat %q not known", logFormat) - } - - err := SetLogLevel(level) - if err != nil { - return nil, err - } - - return &log.Logger, nil -} diff --git a/pkg/logging/slog.go b/pkg/logging/slog.go new file mode 100644 index 0000000..f5c4abb --- /dev/null +++ b/pkg/logging/slog.go @@ -0,0 +1,127 @@ +// Copyright 2023, DASH-Industry Forum. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE.md file. +package logging + +import ( + "fmt" + "log/slog" + "net/http" + "runtime/debug" + "strings" + "time" + + "github.com/go-chi/chi/v5/middleware" +) + +// Different types of logging +const ( + LogText string = "text" + LogJSON string = "json" + LogPretty string = "pretty" + LogDiscard string = "discard" +) + +var logLevel *slog.LevelVar + +// LogFormats returns the allowed log formats. +var LogFormats = []string{LogText, LogJSON, LogPretty, LogDiscard} + +// LogLevels returns the allowed log levels. +var LogLevels = []string{"DEBUG", "INFO", "WARN", "ERROR"} + +// LogLevel returns the current log level. +func LogLevel() string { + l := logLevel.Level() + return l.String() +} + +// parseLevel parses a log level string. If the string is empty, INFO is assumed. +func parseLevel(level string) (slog.Level, error) { + level = strings.ToUpper(level) + switch level { + case "DEBUG": + return slog.LevelDebug, nil + case "INFO", "": + return slog.LevelInfo, nil + case "WARN": + return slog.LevelWarn, nil + case "ERROR": + return slog.LevelError, nil + default: + return slog.LevelDebug, fmt.Errorf("log level %q not known", level) + } +} + +// SetLogLevel sets the global log level +func SetLogLevel(level string) error { + l, err := parseLevel(level) + if err != nil { + return err + } + logLevel.Set(l) + return nil +} + +// SlogMiddleWare logs access and converts panic to stack traces. +func SlogMiddleWare(l *slog.Logger) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + startTime := time.Now() + inPath := r.URL.Path + + defer func() { + endTime := time.Now() + + // Recover and record stack traces in case of a panic + if rec := recover(); rec != nil { + l.Error("Runtime error (panic)", + "request_id", GetRequestID(r), + "recover_info", rec, + "debug_stack", debug.Stack()) + http.Error(ww, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) + } + + latency_ms := fmt.Sprintf("%.3f", float64(endTime.Sub(startTime).Nanoseconds())/1000000.0) + l2 := l.With( + "request_id", GetRequestID(r), + "remote_ip", r.RemoteAddr, + "proto", r.Proto, + "method", r.Method, + "user_agent", r.Header.Get("User-Agent"), + "status", ww.Status(), + "latency_ms", latency_ms, + "bytes_out", ww.BytesWritten()) + if inPath != r.URL.Path { + l2 = l2.With("url", inPath, "location", r.URL.Path) + } else { + l2 = l2.With("url", r.URL.Path) + } + + bytesIn := r.Header.Get("Content-Length") + if bytesIn != "" { + l2 = l2.With("bytes_in", bytesIn) + } + l2.Info("request") + next.ServeHTTP(ww, r) + }() + } + return http.HandlerFunc(fn) + } +} + +// GetRequestID returns the request ID. +func GetRequestID(r *http.Request) string { + key := middleware.RequestIDKey + requestID, ok := r.Context().Value(key).(string) + if !ok { + requestID = "-" + } + return requestID +} + +// SubLoggerWithRequestID creates a new sub-logger with request_id field. +func SubLoggerWithRequestID(l *slog.Logger, r *http.Request) *slog.Logger { + return l.With(slog.String("request_id", GetRequestID(r))) +} diff --git a/pkg/logging/slog_test.go b/pkg/logging/slog_test.go new file mode 100644 index 0000000..430ac92 --- /dev/null +++ b/pkg/logging/slog_test.go @@ -0,0 +1,36 @@ +// Copyright 2023, DASH-Industry Forum. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE.md file. + +package logging + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +func TestInitSlog(t *testing.T) { + cases := []struct { + format string + level string + expectErr bool + }{ + {"text", "DEBUG", false}, + {"json", "INFO", false}, + {"json", "WARN", false}, + {"text", "ERROR", false}, + {"fish", "DEBUG", true}, + {"text", "FISH", true}, + } + + for _, c := range cases { + err := InitSlog(c.level, c.format) + if c.expectErr { + require.Error(t, err, "InitSlog(%q, %q) should fail", c.level, c.format) + } else { + require.NoError(t, err) + require.Equal(t, c.level, LogLevel()) + } + } +} diff --git a/pkg/logging/zerolog.go b/pkg/logging/zerolog.go deleted file mode 100644 index f11ee31..0000000 --- a/pkg/logging/zerolog.go +++ /dev/null @@ -1,194 +0,0 @@ -// Copyright 2023, DASH-Industry Forum. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE.md file. - -package logging - -import ( - "fmt" - "net/http" - "os" - "runtime/debug" - "time" - - "github.com/go-chi/chi/v5/middleware" - "github.com/rs/zerolog" - "github.com/rs/zerolog/log" -) - -type Logger = zerolog.Logger - -// Different types of logging -const ( - LogConsolePretty string = "consolepretty" - LogJSON string = "json" - LogDiscard string = "discard" - LogJournald string = "journald" -) - -var LogFormats = []string{LogJSON, LogConsolePretty, LogJournald, LogDiscard} -var LogFormatsCommandLine = []string{LogJSON, LogConsolePretty, LogDiscard} - -var LogLevels = []string{"trace", "debug", "info", "warn", "error", "fatal", "panic"} - -// init sets the time zone to UTC. -func init() { - zerolog.TimestampFunc = func() time.Time { - return time.Now().UTC() - } -} - -func isValidLogFormat(logFormat string) bool { - for _, lf := range LogFormats { - if lf == logFormat { - return true - } - } - return false -} - -// GetGlobalLogger returns the global logger instance. -func GetGlobalLogger() *Logger { - return &log.Logger -} - -// GetLogLevel returns the current global log level. -func GetLogLevel() string { - return zerolog.GlobalLevel().String() -} - -// SetLogLevel sets the global log level. -func SetLogLevel(level string) error { - logLevel, err := zerolog.ParseLevel(level) - if err != nil { - return fmt.Errorf("could not parse log level %q", level) - } - zerolog.SetGlobalLevel(logLevel) - return nil -} - -// SetLogFile creates a new global logger that writes to a file. -func SetLogFile(filename string) (*os.File, error) { - file, err := os.OpenFile( - filename, - os.O_APPEND|os.O_CREATE|os.O_WRONLY, - 0664, - ) - if err != nil { - return nil, err - } - log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: file, NoColor: true, TimeFormat: time.RFC3339}). - With().Timestamp().Logger() - - return file, nil -} - -// ZerologMiddleware logs access and converts panic to stack traces. -func ZerologMiddleware(logger *zerolog.Logger) func(next http.Handler) http.Handler { - return func(next http.Handler) http.Handler { - fn := func(w http.ResponseWriter, r *http.Request) { - ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) - startTime := time.Now() - inPath := r.URL.Path - - defer func() { - endTime := time.Now() - errorLog := SubLoggerWithRequestIDAndTopic(r, "error") - - // Recover and record stack traces in case of a panic - if rec := recover(); rec != nil { - errorLog.Panic(). - Timestamp(). - Interface("recover_info", rec). - Bytes("debug_stack", debug.Stack()). - Msg("Runtime error (panic)") - http.Error(ww, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - } - - accessLog := SubLoggerWithRequestIDAndTopic(r, "access") - al := accessLog.Info(). - Timestamp(). - Str("remote_ip", r.RemoteAddr). - Str("proto", r.Proto). - Str("method", r.Method). - Str("user_agent", r.Header.Get("User-Agent")). - Int("status", ww.Status()). - Str("latency_ms", fmt.Sprintf("%.3f", float64(endTime.Sub(startTime).Nanoseconds())/1000000.0)). - Int("bytes_out", ww.BytesWritten()) - if inPath != r.URL.Path { - al = al.Str("url", inPath). - Str("location", r.URL.Path) - } else { - al = al.Str("url", r.URL.Path) - } - bytesIn := r.Header.Get("Content-Length") - if bytesIn != "" { - al.Str("bytes_in", bytesIn) - } - al.Msg("Incoming request") - }() - next.ServeHTTP(ww, r) - } - return http.HandlerFunc(fn) - } -} - -// GetRequestID returns the request ID. -func GetRequestID(r *http.Request) string { - key := middleware.RequestIDKey - requestID, ok := r.Context().Value(key).(string) - if !ok { - requestID = "-" - } - return requestID -} - -// SubLoggerWithRequestID creates a new sub-logger with request_id field. -func SubLoggerWithRequestID(r *http.Request) *zerolog.Logger { - logger := log.Logger.With(). - Str("request_id", GetRequestID(r)). - Logger() - return &logger -} - -// SubLoggerWithRequestIDAndTopic creates a new sub-logger with request_id and topic fields. -func SubLoggerWithRequestIDAndTopic(r *http.Request, topic string) *zerolog.Logger { - logger := log.Logger.With(). - Str("request_id", GetRequestID(r)). - Str("topic", topic). - Logger() - return &logger -} - -// SubLoggerWithTopic creates sub-logger with topic field. -func SubLoggerWithTopic(lg *zerolog.Logger, topic string) *zerolog.Logger { - logger := lg.With().Str("topic", topic).Logger() - return &logger -} - -// LoggerWithTopic creates a top-level logger with topic field. -func LoggerWithTopic(topic string) *zerolog.Logger { - logger := log.Logger.With(). - Str("topic", topic). - Logger() - return &logger -} - -// SubLogger create a new sub-logger with a specific key, value field. -func SubLoggerWithString(key string, val string) *zerolog.Logger { - logger := log.Logger.With(). - Str(key, val). - Logger() - return &logger -} - -// SubLogger creates a new sub-logger with a specific log level. -func SubLoggerWithSpecificLevel(lg *zerolog.Logger, level string) *zerolog.Logger { - logLevel, err := zerolog.ParseLevel(level) - if err != nil { - logLevel = zerolog.TraceLevel - } - - logger := lg.Level(logLevel) - return &logger -} diff --git a/pkg/logging/zerolog_test.go b/pkg/logging/zerolog_test.go deleted file mode 100644 index 97a8cef..0000000 --- a/pkg/logging/zerolog_test.go +++ /dev/null @@ -1,36 +0,0 @@ -// Copyright 2023, DASH-Industry Forum. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE.md file. - -package logging - -import ( - "testing" - - "github.com/rs/zerolog" - "github.com/stretchr/testify/require" -) - -func TestInitZerolog(t *testing.T) { - logger, err := InitZerolog("debug", LogConsolePretty) - require.NoError(t, err) - require.Equal(t, zerolog.DebugLevel, zerolog.GlobalLevel()) - logger.Info().Msg("Should show 1") - - // For some reason output is not JSON-formatted when logging from within a test - logger, err = InitZerolog("info", LogJSON) - require.NoError(t, err) - require.Equal(t, zerolog.InfoLevel, zerolog.GlobalLevel()) - logger.Info().Msg("Should show 2") - - logger, err = InitZerolog("warn", LogConsolePretty) - require.NoError(t, err) - require.Equal(t, zerolog.WarnLevel, zerolog.GlobalLevel()) - logger.Info().Msg("Should not show") - - _, err = InitZerolog("fish", LogJSON) - require.Error(t, err) - - _, err = InitZerolog("debug", "party") - require.Error(t, err) -}