From f0ee76c29aec0a143cac4811d8f11bc3410dd735 Mon Sep 17 00:00:00 2001 From: Moshe Immermam Date: Sun, 18 Aug 2024 21:36:36 +0300 Subject: [PATCH 1/2] chore: logging improvements --- logger/caller.go | 15 +++++ logger/default.go | 3 +- logger/log.go | 28 ++++++++++ logger/slog.go | 137 ++++++++++++++++++++++++++++++---------------- 4 files changed, 136 insertions(+), 47 deletions(-) diff --git a/logger/caller.go b/logger/caller.go index 6666fff..515f98c 100644 --- a/logger/caller.go +++ b/logger/caller.go @@ -1,6 +1,7 @@ package logger import ( + "path" "runtime" "strconv" "strings" @@ -67,6 +68,20 @@ func skipFrame(frame runtime.Frame) bool { return false } +func GetCaller(pc ...uintptr) string { + frames := runtime.CallersFrames(pc) + for { + frame, more := frames.Next() + if !skipFrame(frame) { + + return path.Base(path.Dir(frame.File)) + "/" + path.Base(frame.File) + } + if !more { + return "" + } + } +} + func CallerPC(skip ...int) uintptr { pcs := [13]uintptr{} len := runtime.Callers(1, pcs[:]) diff --git a/logger/default.go b/logger/default.go index 9216407..c70c7c4 100644 --- a/logger/default.go +++ b/logger/default.go @@ -11,7 +11,7 @@ import ( ) var currentLogger Logger -var color, reportCaller, jsonLogs bool +var color, reportCaller, jsonLogs, logToStderr bool var level int func init() { @@ -27,6 +27,7 @@ func BindFlags(flags *pflag.FlagSet) { flags.BoolVar(&jsonLogs, "json-logs", false, "Print logs in json format to stderr") flags.BoolVar(&color, "color", true, "Print logs using color") flags.BoolVar(&reportCaller, "report-caller", false, "Report log caller info") + flags.BoolVar(&logToStderr, "log-to-stderr", false, "Log to stderr instead of stdout") } func BindGoFlags() { diff --git a/logger/log.go b/logger/log.go index 0d6dce0..e847ff8 100644 --- a/logger/log.go +++ b/logger/log.go @@ -45,6 +45,34 @@ const ( Silent LogLevel = 10 ) +func (l LogLevel) String() string { + switch l { + case Debug: + return "debug" + case Trace: + return "trace" + case Trace1: + return "trace1" + case Trace2: + return "trace2" + case Trace3: + return "trace3" + case Trace4: + return "trace4" + case Info: + return "info" + case Warn: + return "warn" + case Error: + return "error" + case Fatal: + return "fatal" + case Silent: + return "silent" + } + return "" +} + const ( cyan = "\x1b[36" Cyan = cyan + Normal diff --git a/logger/slog.go b/logger/slog.go index 6ba1b16..7a60d86 100644 --- a/logger/slog.go +++ b/logger/slog.go @@ -9,13 +9,13 @@ import ( "strconv" "strings" "time" + "unicode" "github.com/flanksource/commons/is" "github.com/flanksource/commons/properties" "github.com/kr/pretty" "github.com/lmittmann/tint" "github.com/lrita/cmap" - "github.com/samber/lo" ) var ( @@ -28,14 +28,14 @@ var todo = context.TODO() func GetNamedLoggingLevels() (levels map[string]string) { levels = make(map[string]string) namedLoggers.Range(func(key string, value *SlogLogger) bool { - levels[key] = value.Level.String() + levels[key] = FromSlogLevel(value.Level.Level()).String() return true }) return levels } func BrightF(msg string, args ...interface{}) string { - if !color || isTTY && !jsonLogs { + if isTTY && color && !jsonLogs { return DarkWhite + fmt.Sprintf(msg, args...) + Reset } return fmt.Sprintf(msg, args...) @@ -54,7 +54,6 @@ func GetSlogLogger() SlogLogger { func onPropertyUpdate(props *properties.Properties) { for k, v := range props.GetAll() { - if k == "log.level" || k == "log.json" || k == "log.caller" || k == "log.color" { root := New("root") existing := GetLogger() @@ -69,35 +68,50 @@ func onPropertyUpdate(props *properties.Properties) { reportCaller, _ = strconv.ParseBool(v) } } + + if props.On(false, "log.json") && props.On(false, "log.color") { + // disable color logs when json logs are enabled + properties.Set("log.color", "false") + } } func New(prefix string) *SlogLogger { // create a new slogger - var slogger *slog.Logger + var logger *SlogLogger var lvl = &slog.LevelVar{} var l any - reportCaller := properties.On(false, fmt.Sprintf("log.caller.%s", prefix), "log.caller") - logJson := properties.On(false, fmt.Sprintf("log.json.%s", prefix), "log.json") - logColor := properties.On(false, fmt.Sprintf("log.color.%s", prefix), "log.color") + reportCaller := properties.On(reportCaller, fmt.Sprintf("log.caller.%s", prefix), "log.caller") + logJson := properties.On(jsonLogs, "log.json") + logColor := properties.On(color, fmt.Sprintf("log.color.%s", prefix), "log.color") logLevel := properties.String("", fmt.Sprintf("log.level.%s", prefix), "log.level") - if logJson { - slogger = slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{ - AddSource: reportCaller, - Level: lvl, - })) - } else { - slogger = slog.New(tint.NewHandler(os.Stderr, &tint.Options{ - Level: lvl, - NoColor: !logColor, - AddSource: reportCaller, - TimeFormat: properties.String("15:04:05.999", fmt.Sprintf("log.time.format.%s", prefix), "log.time.format"), - })) + logStderr := properties.On(logToStderr, "log.stderr") + destination := os.Stdout + if logStderr { + destination = os.Stderr } - logger := SlogLogger{ - Logger: slogger, - Level: lvl, + if logJson { + color = false + jsonLogs = true + logger = &SlogLogger{ + Level: lvl, + Logger: slog.New(slog.NewJSONHandler(destination, &slog.HandlerOptions{ + AddSource: reportCaller, + Level: lvl, + })), + } + + } else { + logger = &SlogLogger{ + Logger: slog.New(tint.NewHandler(destination, &tint.Options{ + Level: lvl, + NoColor: !logColor, + AddSource: reportCaller, + TimeFormat: properties.String("15:04:05.999", fmt.Sprintf("log.time.format.%s", prefix), "log.time.format"), + })), + Level: lvl, + } } if logLevel != "" { @@ -106,11 +120,12 @@ func New(prefix string) *SlogLogger { l = level } - if prefix != "" { - logger.Prefix = fmt.Sprintf("[%s] ", BrightF(prefix)) + if prefix != "" && prefix != "root" { + logger.Prefix = prefix } + logger.SetLogLevel(l) - return &logger + return logger } func UseSlog() { if currentLogger != nil { @@ -126,6 +141,20 @@ func UseSlog() { properties.RegisterListener(onPropertyUpdate) } +func camelCaseWords(s string) []string { + var result strings.Builder + for _, r := range s { + if unicode.IsUpper(r) { + result.WriteRune(' ') + result.WriteRune(r) + + } else { + result.WriteRune(r) + } + } + return strings.Fields(result.String()) +} + func GetLogger(names ...string) *SlogLogger { parent, _ := namedLoggers.Load("root") if len(names) == 0 { @@ -133,19 +162,18 @@ func GetLogger(names ...string) *SlogLogger { } path := "" - for _, name := range names { - if !strings.Contains(name, " ") { - name = strings.ToLower(strings.Join(lo.Words(name), " ")) - } else { - name = strings.ToLower(name) - } + for i, name := range names { + name = strings.ToLower(strings.Join(camelCaseWords(name), " ")) if path != "" { path += "." } - path = path + name + path = path + strings.TrimSpace(name) if v, ok := namedLoggers.Load(path); ok { return v } + if i == 0 { + break + } } child, _ := namedLoggers.LoadOrStore(path, New(path)) return child @@ -163,8 +191,8 @@ func (s SlogLogger) Warnf(format string, args ...interface{}) { if !s.Logger.Enabled(todo, slog.LevelWarn) { return } - r := slog.NewRecord(time.Now(), slog.LevelWarn, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) - _ = s.Logger.Handler().Handle(context.Background(), r) + s.handle(slog.NewRecord(time.Now(), slog.LevelWarn, "", CallerPC()), format, args...) + } func (s SlogLogger) GetSlogLogger() *slog.Logger { @@ -175,8 +203,7 @@ func (s SlogLogger) Infof(format string, args ...interface{}) { if !s.Logger.Enabled(todo, slog.LevelInfo) { return } - r := slog.NewRecord(time.Now(), slog.LevelInfo, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) - _ = s.Logger.Handler().Handle(context.Background(), r) + s.handle(slog.NewRecord(time.Now(), slog.LevelInfo, "", CallerPC()), format, args...) } func (s SlogLogger) Secretf(format string, args ...interface{}) { @@ -191,15 +218,34 @@ func (s SlogLogger) Errorf(format string, args ...interface{}) { if !s.Logger.Enabled(todo, slog.LevelError) { return } - r := slog.NewRecord(time.Now(), slog.LevelError, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) - _ = s.Logger.Handler().Handle(context.Background(), r) + s.handle(slog.NewRecord(time.Now(), slog.LevelError, "", CallerPC()), format, args...) } func (s SlogLogger) Debugf(format string, args ...interface{}) { if !s.Logger.Enabled(context.Background(), slog.LevelDebug) { return } - r := slog.NewRecord(time.Now(), slog.LevelDebug, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) + s.handle(slog.NewRecord(time.Now(), slog.LevelDebug, "", CallerPC()), format, args...) + +} + +func (s SlogLogger) handle(r slog.Record, format string, args ...interface{}) { + caller := GetCaller(r.PC) + if fileLogger, ok := namedLoggers.Load(caller); ok { + if !fileLogger.IsLevelEnabled(FromSlogLevel(r.Level)) { + return + } + } + if jsonLogs { + if s.Prefix != "" { + r.Add("logger", s.Prefix) + } + r.Message = fmt.Sprintf(format, args...) + } else if s.Prefix != "" { + r.Message = fmt.Sprintf(fmt.Sprintf("(%s) ", BrightF(s.Prefix))+format, args...) + } else { + r.Message = fmt.Sprintf(format, args...) + } _ = s.Logger.Handler().Handle(context.Background(), r) } @@ -207,13 +253,12 @@ func (s SlogLogger) Tracef(format string, args ...interface{}) { if !s.Logger.Enabled(todo, SlogTraceLevel) { return } - r := slog.NewRecord(time.Now(), SlogTraceLevel, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) - _ = s.Logger.Handler().Handle(context.Background(), r) + s.handle(slog.NewRecord(time.Now(), SlogTraceLevel, "", CallerPC()), format, args...) + } func (s SlogLogger) Fatalf(format string, args ...interface{}) { - r := slog.NewRecord(time.Now(), SlogFatal, fmt.Sprintf(s.Prefix+format, args...), CallerPC()) - _ = s.Logger.Handler().Handle(context.Background(), r) + s.handle(slog.NewRecord(time.Now(), SlogFatal, "", CallerPC()), format, args...) } type slogVerbose struct { @@ -226,8 +271,8 @@ func (v slogVerbose) Infof(format string, args ...interface{}) { return } - r := slog.NewRecord(time.Now(), v.level, fmt.Sprintf(v.Prefix+format, args...), CallerPC()) - _ = v.Logger.Handler().Handle(context.Background(), r) + v.handle(slog.NewRecord(time.Now(), v.level, "", CallerPC()), format, args...) + } func (v slogVerbose) Enabled() bool { From d48ac9f126c1c6e86eb75f5e7b9ebe2bf1428d98 Mon Sep 17 00:00:00 2001 From: Moshe Immermam Date: Sun, 18 Aug 2024 22:23:45 +0300 Subject: [PATCH 2/2] feat: watch property file changes --- go.mod | 1 + go.sum | 4 ++++ logger/slog.go | 12 +++++----- properties/properties.go | 49 +++++++++++++++++++++++++++++++++++----- 4 files changed, 54 insertions(+), 12 deletions(-) diff --git a/go.mod b/go.mod index 6f60f48..1066279 100644 --- a/go.mod +++ b/go.mod @@ -52,6 +52,7 @@ require ( github.com/flanksource/gomplate/v3 v3.24.22 // indirect github.com/flanksource/is-healthy v1.0.26 // indirect github.com/flanksource/kubectl-neat v1.0.4 // indirect + github.com/fsnotify/fsnotify v1.7.0 // indirect github.com/ghodss/yaml v1.0.0 // indirect github.com/go-logr/logr v1.4.1 // indirect github.com/go-logr/stdr v1.2.2 // indirect diff --git a/go.sum b/go.sum index 68c6a31..d512f7f 100644 --- a/go.sum +++ b/go.sum @@ -692,6 +692,8 @@ github.com/envoyproxy/protoc-gen-validate v0.9.1/go.mod h1:OKNgG7TCp5pF4d6XftA0+ github.com/envoyproxy/protoc-gen-validate v1.0.2 h1:QkIBuU5k+x7/QXPvPPnWXWlCdaBFApVqftFV6k087DA= github.com/envoyproxy/protoc-gen-validate v1.0.2/go.mod h1:GpiZQP3dDbg4JouG/NNS7QWXpgx6x8QiMKdmN72jogE= github.com/evanphx/json-patch v4.12.0+incompatible/go.mod h1:50XU6AFN0ol/bzJsmQLiYLvXMP4fmwYFNcr97nuDLSk= +github.com/fatih/camelcase v1.0.0 h1:hxNvNX/xYBp0ovncs8WyWZrOrpBNub/JfaMvbURyft8= +github.com/fatih/camelcase v1.0.0/go.mod h1:yN2Sb0lFhZJUdVvtELVWefmrXpuZESvPmqwoZc+/fpc= github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4= github.com/felixge/httpsnoop v1.0.4 h1:NFTV2Zj1bL4mc9sqWACXbQFVBBg2W3GPvqp8/ESS2Wg= github.com/felixge/httpsnoop v1.0.4/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U= @@ -707,6 +709,8 @@ github.com/fogleman/gg v1.2.1-0.20190220221249-0403632d5b90/go.mod h1:R/bRT+9gY/ github.com/fogleman/gg v1.3.0/go.mod h1:R/bRT+9gY/C5z7JzPU0zXsXHKM4/ayA+zqcVNZzPa1k= github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo= github.com/fsnotify/fsnotify v1.4.9/go.mod h1:znqG4EE+3YCdAaPaxE2ZRY/06pZUdp0tY4IgpuI1SZQ= +github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA= +github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM= github.com/getkin/kin-openapi v0.76.0/go.mod h1:660oXbgy5JFMKreazJaQTw7o+X00qeSyhcnluiMv+Xg= github.com/ghodss/yaml v1.0.0 h1:wQHKEahhL6wmXdzwWG11gIVCkOv05bNOh+Rxn0yngAk= github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= diff --git a/logger/slog.go b/logger/slog.go index 7a60d86..b3b4ec7 100644 --- a/logger/slog.go +++ b/logger/slog.go @@ -230,12 +230,12 @@ func (s SlogLogger) Debugf(format string, args ...interface{}) { } func (s SlogLogger) handle(r slog.Record, format string, args ...interface{}) { - caller := GetCaller(r.PC) - if fileLogger, ok := namedLoggers.Load(caller); ok { - if !fileLogger.IsLevelEnabled(FromSlogLevel(r.Level)) { - return - } - } + // caller := GetCaller(r.PC) + // if fileLogger, ok := namedLoggers.Load(caller); ok { + // if !fileLogger.IsLevelEnabled(FromSlogLevel(r.Level)) { + // return + // } + // } if jsonLogs { if s.Prefix != "" { r.Add("logger", s.Prefix) diff --git a/properties/properties.go b/properties/properties.go index a49df75..ce71dcb 100644 --- a/properties/properties.go +++ b/properties/properties.go @@ -10,16 +10,25 @@ import ( "strconv" "strings" "sync" + + "github.com/fsnotify/fsnotify" ) var Global = &Properties{ m: make(map[string]string), } +var LoadFile = func(filename string) error { + return Global.LoadFile(filename) +} + type Properties struct { m map[string]string + filename string listeners []func(*Properties) lock sync.RWMutex + close func() + Reload func() } func (p *Properties) RegisterListener(fn func(*Properties)) { @@ -28,9 +37,9 @@ func (p *Properties) RegisterListener(fn func(*Properties)) { func (p *Properties) Set(key string, value any) { p.lock.Lock() + defer p.notify() defer p.lock.Unlock() p.m[key] = fmt.Sprintf("%v", value) - p.notify() } func (p *Properties) notify() { @@ -63,10 +72,6 @@ func (p *Properties) Update(props map[string]string) { } } -func LoadFile(filename string) error { - return Global.LoadFile(filename) -} - func (p *Properties) LoadFile(filename string) error { if !path.IsAbs(filename) { cwd, _ := os.Getwd() @@ -80,7 +85,13 @@ func (p *Properties) LoadFile(filename string) error { return err } defer file.Close() - slog.Info(fmt.Sprintf("loading properties from %s", filename)) + p.filename = filename + + if p.close == nil { + p.close = p.Watch() + } + + slog.Info(fmt.Sprintf("Loading properties from %s", filename)) var props = make(map[string]string) scanner := bufio.NewScanner(file) for scanner.Scan() { @@ -161,3 +172,29 @@ func (p *Properties) Int(def int, key string) int { } return def } + +func (p *Properties) Watch() func() { + if p.close != nil { + return p.close + } + slog.Info(fmt.Sprintf("Watching %s for changes", p.filename)) + // Create new watcher. + watcher, err := fsnotify.NewWatcher() + if err != nil { + slog.Warn("Failed to create watcher for properties file: " + err.Error()) + } + + _ = watcher.Add(path.Dir(p.filename)) + + go func() { + + for e := range watcher.Events { + if e.Name == p.filename && e.Op != fsnotify.Chmod { + p.LoadFile(p.filename) + } + } + }() + return func() { + _ = watcher.Close() + } +}