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

@@ -83,6 +83,7 @@ type Log struct {
 	AccessFormat string
 	AccessTarget string
 	RoutesFormat string
+	Level        string
 }
 
 type Metrics struct {

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}}",

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")

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 {

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

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 + "???"
+	}
+}

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)
+			}
+		})
+	}
+}

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())