From 535100658bfb1520473dc6d1cb0e7b45b86351c7 Mon Sep 17 00:00:00 2001 From: Frank Schroeder Date: Mon, 9 Oct 2017 02:12:21 +0200 Subject: [PATCH] log: add leveled logging This patch implements a simple leveled logging output to provide the ability to have DEBUG logs which are not logged by default. The implementation allows changing the log level at runtime but in this implementation there is no mechanism to change the value at runtime. Closes #366 --- config/config.go | 1 + config/default.go | 1 + config/load.go | 1 + config/load_test.go | 7 +++ fabio.properties | 9 ++++ logger/level_writer.go | 98 +++++++++++++++++++++++++++++++++++++ logger/level_writer_test.go | 46 +++++++++++++++++ main.go | 10 ++++ 8 files changed, 173 insertions(+) create mode 100644 logger/level_writer.go create mode 100644 logger/level_writer_test.go diff --git a/config/config.go b/config/config.go index bf67484b4..135a80b8a 100644 --- a/config/config.go +++ b/config/config.go @@ -83,6 +83,7 @@ type Log struct { AccessFormat string AccessTarget string RoutesFormat string + Level string } type Metrics struct { diff --git a/config/default.go b/config/default.go index f77ad0483..044c470e3 100644 --- a/config/default.go +++ b/config/default.go @@ -23,6 +23,7 @@ var defaultConfig = &Config{ Log: Log{ AccessFormat: "common", RoutesFormat: "delta", + Level: "INFO", }, Metrics: Metrics{ Prefix: "{{clean .Hostname}}.{{clean .Exec}}", diff --git a/config/load.go b/config/load.go index 8fd677521..96d479c9c 100644 --- a/config/load.go +++ b/config/load.go @@ -138,6 +138,7 @@ func load(cmdline, environ, envprefix []string, props *properties.Properties) (c f.StringVar(&cfg.Log.AccessFormat, "log.access.format", defaultConfig.Log.AccessFormat, "access log format") f.StringVar(&cfg.Log.AccessTarget, "log.access.target", defaultConfig.Log.AccessTarget, "access log target") f.StringVar(&cfg.Log.RoutesFormat, "log.routes.format", defaultConfig.Log.RoutesFormat, "log format of routing table updates") + f.StringVar(&cfg.Log.Level, "log.level", defaultConfig.Log.Level, "log level: TRACE, DEBUG, INFO, WARN, ERROR, FATAL") f.StringVar(&cfg.Metrics.Target, "metrics.target", defaultConfig.Metrics.Target, "metrics backend") f.StringVar(&cfg.Metrics.Prefix, "metrics.prefix", defaultConfig.Metrics.Prefix, "prefix for reported metrics") f.StringVar(&cfg.Metrics.Names, "metrics.names", defaultConfig.Metrics.Names, "route metric name template") diff --git a/config/load_test.go b/config/load_test.go index a41fc38aa..a912ad00f 100644 --- a/config/load_test.go +++ b/config/load_test.go @@ -543,6 +543,13 @@ func TestLoad(t *testing.T) { return cfg }, }, + { + args: []string{"-log.level", "foobar"}, + cfg: func(cfg *Config) *Config { + cfg.Log.Level = "foobar" + return cfg + }, + }, { args: []string{"-metrics.target", "some-target"}, cfg: func(cfg *Config) *Config { diff --git a/fabio.properties b/fabio.properties index af77e9d58..a3c1d88a0 100644 --- a/fabio.properties +++ b/fabio.properties @@ -456,6 +456,15 @@ # log.access.target = +# log.level configures the log level. +# +# Valid levels are TRACE, DEBUG, INFO, WARN, ERROR and FATAL. +# +# The default is +# +# log.level = INFO + + # log.routes.format configures the log output format of routing table updates. # # Changes to the routing table are written to the standard log. This option diff --git a/logger/level_writer.go b/logger/level_writer.go new file mode 100644 index 000000000..8fb94bd67 --- /dev/null +++ b/logger/level_writer.go @@ -0,0 +1,98 @@ +package logger + +import ( + "fmt" + "io" + "strings" + "sync/atomic" +) + +// LevelWriter implements a simplistic levelled log writer which supports +// TRACE, DEBUG, INFO, WARN, ERROR and FATAL. The log level can be changed at +// runtime. +type LevelWriter struct { + w io.Writer + level atomic.Value // string + prefixLen int +} + +// NewLevelWriter creates a new leveled writer for the given output and a +// default level. Prefix is the string that is expected before the opening +// bracket and usually depends on the chosen log format. For the default log +// format prefix should be set to "2017/01/01 00:00:00 " whereby only the +// format and the spaces are relevant but not the date and time itself. +func NewLevelWriter(w io.Writer, level, prefix string) *LevelWriter { + lw := &LevelWriter{w: w, prefixLen: len(prefix)} + if !lw.SetLevel(level) { + panic(fmt.Sprintf("invalid log level %s", level)) + } + return lw +} + +func (w *LevelWriter) Write(b []byte) (int, error) { + // check if the log line starts with the prefix + if len(b) < w.prefixLen+2 || b[w.prefixLen] != '[' { + return fmt.Fprint(w.w, "invalid log msg: ", string(b)) + } + + // determine the level by looking at the character after the opening + // bracket. + level := rune(b[w.prefixLen+1]) // T, D, I, W, E, or F + + // w.level contains the characters of all the allowed levels so we can just + // check whether the level character is in that set. + if strings.ContainsRune(w.level.Load().(string), level) { + return w.w.Write(b) + } + return 0, nil +} + +// SetLevel sets the log level to the new value and returns true +// if that was successful. +func (w *LevelWriter) SetLevel(s string) bool { + // levels contains the first character of the levels in descending order + const levels = "TDIWEF" + switch strings.ToUpper(s) { + case "TRACE": + w.level.Store(levels[0:]) + return true + case "DEBUG": + w.level.Store(levels[1:]) + return true + case "INFO": + w.level.Store(levels[2:]) + return true + case "WARN": + w.level.Store(levels[3:]) + return true + case "ERROR": + w.level.Store(levels[4:]) + return true + case "FATAL": + w.level.Store(levels[5:]) + return true + default: + return false + } +} + +// Level returns the current log level. +func (w *LevelWriter) Level() string { + l := w.level.Load().(string) + switch l[0] { + case 'T': + return "TRACE" + case 'D': + return "DEBUG" + case 'I': + return "INFO" + case 'W': + return "WARN" + case 'E': + return "ERROR" + case 'F': + return "FATAL" + default: + return "???" + l + "???" + } +} diff --git a/logger/level_writer_test.go b/logger/level_writer_test.go new file mode 100644 index 000000000..068cddfde --- /dev/null +++ b/logger/level_writer_test.go @@ -0,0 +1,46 @@ +package logger + +import ( + "bytes" + "reflect" + "strings" + "testing" +) + +func TestLevelWriter(t *testing.T) { + input := []string{ + "2017/01/01 00:00:00 [TRACE] a", + "2017/01/01 00:00:00 [DEBUG] a", + "2017/01/01 00:00:00 [INFO] a", + "2017/01/01 00:00:00 [WARN] a", + "2017/01/01 00:00:00 [ERROR] a", + "2017/01/01 00:00:00 [FATAL] a", + } + tests := []struct { + level string + out []string + }{ + {"TRACE", input}, + {"DEBUG", input[1:]}, + {"INFO", input[2:]}, + {"WARN", input[3:]}, + {"ERROR", input[4:]}, + {"FATAL", input[5:]}, + } + + for _, tt := range tests { + t.Run(tt.level, func(t *testing.T) { + var b bytes.Buffer + w := NewLevelWriter(&b, tt.level, "2017/01/01 00:00:00 ") + for _, s := range input { + if _, err := w.Write([]byte(s + "\n")); err != nil { + t.Fatal("w.Write:", err) + } + } + out := strings.Split(strings.TrimRight(b.String(), "\n"), "\n") + if got, want := out, tt.out; !reflect.DeepEqual(got, want) { + t.Fatalf("got %#v want %#v", got, want) + } + }) + } +} diff --git a/main.go b/main.go index cb7a72313..dd47dc7ea 100644 --- a/main.go +++ b/main.go @@ -46,7 +46,12 @@ var version = "1.5.2" var shuttingDown int32 +var logOutput logger.LevelWriter + func main() { + logOutput := logger.NewLevelWriter(os.Stderr, "INFO", "2017/01/01 00:00:00 ") + log.SetOutput(logOutput) + cfg, err := config.Load(os.Args, os.Environ()) if err != nil { exit.Fatalf("[FATAL] %s. %s", version, err) @@ -56,6 +61,11 @@ func main() { return } + log.Printf("[INFO] Setting log level to %s", logOutput.Level()) + if !logOutput.SetLevel(cfg.Log.Level) { + log.Printf("[INFO] Cannot set log level to %s", cfg.Log.Level) + } + log.Printf("[INFO] Runtime config\n" + toJSON(cfg)) log.Printf("[INFO] Version %s starting", version) log.Printf("[INFO] Go runtime is %s", runtime.Version())