revendor with fresh lgr, add logger to http server

backend/vendor/github.com/go-pkgz/lgr/README.md

@@ -33,22 +33,53 @@ _Without `lgr.Caller*` it will drop `{caller}` part_
 `lgr.New` call accepts functional options:
 
 - `lgr.Debug` - turn debug mode on to allow messages with "DEBUG" level (filtered overwise)
+- `lgr.Out(io.Writer)` - sets the output writer, default `os.Stdout`
+- `lgr.Err(io.Writer)` - sets the error writer, default `os.Stderr`
 - `lgr.CallerFile` - adds the caller file info
 - `lgr.CallerFunc` - adds the caller function info
 - `lgr.CallerPkg` - adds the caller package
 - `lgr.LevelBraces` - wraps levels with "[" and "]"
 - `lgr.Msec` - adds milliseconds to timestamp
-- `lgr.Out(io.Writer)` - sets the output writer, default `os.Stdout`
-- `lgr.Err(io.Writer)` - sets the error writer, default `os.Stderr`
+- `lgr.Format` - sets custom template, overwrite all other formatting modifiers.
 
+#### formatting templates:
+
+Several predefined templates provided and can be passed directly to `lgr.Format`, i.e. `lgr.Format(lgr.WithMsec)`
+
+```
+	Short      = `{{.DT.Format "2006/01/02 15:04:05"}} {{.Level}} {{.Message}}`
+	WithMsec   = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} {{.Message}}`
+	WithPkg    = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerPkg}}) {{.Message}}`
+	ShortDebug = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFile}}:{{.CallerLine}}) {{.Message}}`
+	FuncDebug  = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFunc}}) {{.Message}}`
+	FullDebug  = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFile}}:{{.CallerLine}} {{.CallerFunc}}) {{.Message}}`
+```
+
+User can make a custom template and pass it directly to `lgr.Format`. For example:
+
+```go    
+    lgr.Format(`{{.Level}} - {{.DT.Format "2006-01-02T15:04:05Z07:00") - {{.CallerPkg}} - {{.Message}}`)
+```
+)
+    
 ### levels
 
-`lgr.Logf` recognizes prefixes like "INFO" or "[INFO]" as levels. The full list of supported levels - "DEBUG", "INFO", "WARN", "ERROR", "PANIC" and "FATAL"
+`lgr.Logf` recognizes prefixes like "INFO" or "[INFO]" as levels. The full list of supported levels - "TRACE", "DEBUG", "INFO", "WARN", "ERROR", "PANIC" and "FATAL"
 
-- `DEBUG` will be filtered unless `lgr.Debug` option defined
+- `TRACE` will be filtered unless `lgr.Trace` option defined
+- `DEBUG` will be filtered unless `lgr.Debug` or `lgr.Trace` options defined
 - `INFO` and `WARN` don't have any special behavior attached
 - `ERROR` sends messages to both out and err writers
 - `PANIC` and `FATAL` send messages to both out and err writers. In addition sends dump of callers and runtime info to err only, and calls `os.Exit(1)`.
+
+### adaptors
+
+`lgr` logger can be converted to `io.Writer` or `*log.Logger`
+
+- `lgr.ToWriter(l lgr.L, level string) io.Writer` - makes io.Writer forwarding write ops to underlying `lgr.L`
+- `lgr.ToStdLogger(l lgr.L, level string) *log.Logger` - makes standard logger on top of `lgr.L`
+
+_`level` parameter is optional, if defined will enforce the level._    
   
 ### global logger
 

backend/vendor/github.com/go-pkgz/lgr/adaptor.go

@@ -0,0 +1,30 @@
+package lgr
+
+import (
+	"log"
+	"strings"
+)
+
+// Writer holds lgr.L and wraps with io.Writer interface
+type Writer struct {
+	L
+	level string // if defined added to each message
+}
+
+// Write to lgr.L, trim EOL
+func (w *Writer) Write(p []byte) (n int, err error) {
+	w.Logf(strings.TrimSuffix(w.level+string(p), "\n"))
+	return len(p), nil
+}
+
+// ToWriter makes io.Writer for given lgr.L with optional level
+func ToWriter(l L, level string) *Writer {
+	if level != "" && !strings.HasSuffix(level, " ") {
+		level += " "
+	}
+	return &Writer{l, level}
+}
+
+func ToStdLogger(l L, level string) *log.Logger {
+	return log.New(ToWriter(l, level), "", 0)
+}

backend/vendor/github.com/go-pkgz/lgr/interface.go

@@ -15,7 +15,7 @@ type L interface {
 // Func type is an adapter to allow the use of ordinary functions as Logger.
 type Func func(format string, args ...interface{})
 
-// Logf calls f(id)
+// Logf calls f(format, args...)
 func (f Func) Logf(format string, args ...interface{}) { f(format, args...) }
 
 // NoOp logger
@@ -26,24 +26,23 @@ var Std = Func(func(format string, args ...interface{}) { stdlog.Printf(format,
 
 // Printf simplifies replacement of std logger
 func Printf(format string, args ...interface{}) {
-	def.Logf(format, args...)
+	def.logf(format, args...)
 }
 
 // Print simplifies replacement of std logger
 func Print(line string) {
-	def.Logf(line)
+	def.logf(line)
 }
 
 // Fatalf simplifies replacement of std logger
 func Fatalf(format string, args ...interface{}) {
-	def.Logf(format, args...)
+	def.logf(format, args...)
 	os.Exit(1)
 }
 
 // Setup default logger with options
 func Setup(opts ...Option) {
 	def = New(opts...)
-	def.callerSkip = 2
 }
 
 // Default returns pre-constructed def logger (debug off, callers disabled)

backend/vendor/github.com/go-pkgz/lgr/logger.go

@@ -1,6 +1,7 @@
 package lgr
 
 import (
+	"bytes"
 	"fmt"
 	"io"
 	"os"
@@ -8,44 +9,94 @@ import (
 	"runtime"
 	"strings"
 	"sync"
+	"text/template"
 	"time"
 )
 
-var levels = []string{"DEBUG", "INFO", "WARN", "ERROR", "PANIC", "FATAL"}
+var levels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "PANIC", "FATAL"}
+
+const (
+	Short      = `{{.DT.Format "2006/01/02 15:04:05"}} {{.Level}} {{.Message}}`
+	WithMsec   = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} {{.Message}}`
+	WithPkg    = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerPkg}}) {{.Message}}`
+	ShortDebug = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFile}}:{{.CallerLine}}) {{.Message}}`
+	FuncDebug  = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFunc}}) {{.Message}}`
+	FullDebug  = `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} ({{.CallerFile}}:{{.CallerLine}} {{.CallerFunc}}) {{.Message}}`
+)
 
 // Logger provided simple logger with basic support of levels. Thread safe
 type Logger struct {
-	stdout, stderr    io.Writer
-	dbg               bool
-	lock              sync.Mutex
-	callerFile        bool
-	callerFunc        bool
-	callerPkg         bool
-	callerSkip        int
-	ignoredPkgCallers []string
+	// set with Option calls
+	stdout, stderr io.Writer // destination writes for out and err
+	dbg            bool      // allows reporting for DEBUG level
+	trace          bool      // allows reporting for TRACE and DEBUG levels
+	callerFile     bool      // reports caller file, i.e. /go/src/github.com/go-pkgz/lgr/logger.go
+	callerFunc     bool      // reports caller function name, i.e. foo/bar.myFunc
+	callerPkg      bool      // reports caller package name
+	levelBraces    bool      // encloses level with [], i.e. [INFO]
+	callerDepth    int       // how many stack frames to skip
+	format         string    // layout template
 
-	now         nowFn
-	fatal       panicFn
-	levelBraces bool
-	msec        bool
+	// internal use
+	now           nowFn
+	fatal         panicFn
+	msec          bool
+	lock          sync.Mutex
+	callerOn      bool
+	levelBracesOn bool
+	templ         *template.Template
 }
 
+// can be redefined internally for testing
 type nowFn func() time.Time
 type panicFn func()
 
-// New makes new leveled logger. Accepts dbg flag turing on info about the caller and allowing DEBUG messages/
+type layout struct {
+	DT         time.Time
+	Level      string
+	Message    string
+	CallerPkg  string
+	CallerFile string
+	CallerFunc string
+	CallerLine int
+}
+
+// New makes new leveled logger. Accepts dbg flag turing on info about the caller and allowing DEBUG messages.
 // Two writers can be passed optionally - first for out and second for err
 func New(options ...Option) *Logger {
+
 	res := Logger{
-		now:        time.Now,
-		fatal:      func() { os.Exit(1) },
-		stdout:     os.Stdout,
-		stderr:     os.Stderr,
-		callerSkip: 1,
+		now:         time.Now,
+		fatal:       func() { os.Exit(1) },
+		stdout:      os.Stdout,
+		stderr:      os.Stderr,
+		callerDepth: 0,
 	}
 	for _, opt := range options {
 		opt(&res)
 	}
+
+	var err error
+	if res.format == "" {
+		res.format = res.templateFromOptions()
+	}
+
+	res.templ, err = template.New("lgr").Parse(res.format)
+	if err != nil {
+		fmt.Printf("invalid template %s, error %v. switched to %s\n", res.format, err, Short)
+		res.format = Short
+		res.templ = template.Must(template.New("lgrDefault").Parse(Short))
+	}
+
+	buf := bytes.Buffer{}
+	if err = res.templ.Execute(&buf, layout{}); err != nil {
+		fmt.Printf("failed to execute template %s, error %v. switched to %s\n", res.format, err, Short)
+		res.format = Short
+		res.templ = template.Must(template.New("lgrDefault").Parse(Short))
+	}
+
+	res.callerOn = strings.Contains(res.format, "{{.Caller")
+	res.levelBracesOn = strings.Contains(res.format, "[{{.Level}}]")
 	return &res
 }
 
@@ -54,92 +105,154 @@ func New(options ...Option) *Logger {
 // ERROR and FATAL also send the same line to err writer.
 // FATAL adds runtime stack and os.exit(1), like panic.
 func (l *Logger) Logf(format string, args ...interface{}) {
+	// to align call depth between (*Logger).Logf() and, for example, Printf()
+	l.logf(format, args...)
+}
 
-	// format timestamp with or without msecs
-	ts := func() (res string) {
-		if l.msec {
-			return l.now().Format("2006/01/02 15:04:05.000")
-		}
-		return l.now().Format("2006/01/02 15:04:05")
-	}
+func (l *Logger) logf(format string, args ...interface{}) {
 
 	lv, msg := l.extractLevel(fmt.Sprintf(format, args...))
 	if lv == "DEBUG" && !l.dbg {
 		return
 	}
-	var bld strings.Builder
-	bld.WriteString(ts())
-	bld.WriteString(l.formatLevel(lv))
-	bld.WriteString(" ")
-
-	if l.callerFile || l.callerFunc || l.callerPkg {
-		if pc, file, line, ok := runtime.Caller(l.callerSkip); ok {
-
-			funcName, fileInfo := "", ""
-
-			if l.callerFunc {
-				funcNameElems := strings.Split(runtime.FuncForPC(pc).Name(), "/")
-				funcName = funcNameElems[len(funcNameElems)-1]
-			}
-
-			if l.callerFile {
-				fnameElems := strings.Split(file, "/")
-				fileInfo = fmt.Sprintf("%s:%d", strings.Join(fnameElems[len(fnameElems)-2:], "/"), line)
-				if l.callerFunc {
-					fileInfo += " "
-				}
-			}
-			// callerPkg only if no other callers
-			if l.callerPkg && !l.callerFile && !l.callerFunc {
-				file = l.ignoreCaller(file)
-				_, fileInfo = path.Split(path.Dir(file))
-				if l.callerFunc {
-					fileInfo += " "
-				}
-			}
-			srcFileInfo := fmt.Sprintf("{%s%s} ", fileInfo, funcName)
-			bld.WriteString(srcFileInfo)
-		}
+	if lv == "TRACE" && !l.trace {
+		return
 	}
 
-	bld.WriteString(msg)  //nolint
-	bld.WriteString("\n") //nolint
+	ci := callerInfo{}
+	if l.callerOn { // optimization to avlod expensive caller evaluation if not in template
+		ci = l.reportCaller(l.callerDepth)
+	}
+
+	elems := layout{
+		DT:         l.now(),
+		Level:      l.formatLevel(lv),
+		Message:    strings.TrimSuffix(msg, "\n"),
+		CallerFunc: ci.FuncName,
+		CallerFile: ci.File,
+		CallerPkg:  ci.Pkg,
+		CallerLine: ci.Line,
+	}
+
+	buf := bytes.Buffer{}
+	err := l.templ.Execute(&buf, elems) // once constructed, a template may be executed safely in parallel.
+	if err != nil {
+		fmt.Printf("failed to execute template, %v\n", err)
+	}
+	buf.WriteString("\n")
+
+	data := buf.Bytes()
+	if l.levelBracesOn {
+		data = bytes.Replace(data, []byte("[WARN ]"), []byte("[WARN] "), 1)
+		data = bytes.Replace(data, []byte("[INFO ]"), []byte("[INFO] "), 1)
+	}
 
 	l.lock.Lock()
-	msgb := []byte(bld.String())
-	l.stdout.Write(msgb) //nolint
+	_, _ = l.stdout.Write(data)
 
+	// write to err as well for high levels
 	switch lv {
 	case "PANIC", "FATAL":
-		l.stderr.Write(msgb)      //nolint
-		bld.WriteString("\n")     //nolint
-		l.stderr.Write(getDump()) //nolint
+		_, _ = l.stderr.Write(data)
+		_, _ = l.stderr.Write(getDump())
 		l.fatal()
 	case "ERROR":
-		l.stderr.Write(msgb) //nolint
+		_, _ = l.stderr.Write(data)
 	}
 
 	l.lock.Unlock()
 }
 
-func (l *Logger) ignoreCaller(p string) string {
-	for _, s := range l.ignoredPkgCallers {
-		if strings.Contains(p, "/"+s+"/") {
-			return strings.Replace(p, "/"+s, "", 1)
-		}
-	}
-	return p
+type callerInfo struct {
+	File     string
+	Line     int
+	FuncName string
+	Pkg      string
 }
 
-func (l *Logger) formatLevel(lv string) string {
+// calldepth 0 identifying the caller of reportCaller()
+func (l *Logger) reportCaller(calldepth int) (res callerInfo) {
 
-	brace := func(b string) string {
-		if l.levelBraces {
-			return b
+	// caller gets file, line number abd function name via runtime.Callers
+	// file looks like /go/src/github.com/go-pkgz/lgr/logger.go
+	// file is an empty string if not known.
+	// funcName looks like:
+	//   main.Test
+	//   foo/bar.Test
+	//   foo/bar.Test.func1
+	//   foo/bar.(*Bar).Test
+	//   foo/bar.glob..func1
+	// funcName is an empty string if not known.
+	// line is a zero if not known.
+	caller := func(calldepth int) (file string, line int, funcName string) {
+		pcs := make([]uintptr, 1)
+		n := runtime.Callers(calldepth, pcs)
+		if n != 1 {
+			return "", 0, ""
 		}
-		return ""
+
+		frame, _ := runtime.CallersFrames(pcs).Next()
+
+		return frame.File, frame.Line, frame.Function
 	}
 
+	// add 5 to adjust stack level because it was called from 3 nested functions added by lgr, i.e. caller,
+	// reportCaller and logf, plus 2 frames by runtime
+	filePath, line, funcName := caller(calldepth + 2 + 3)
+	if (filePath == "") || (line <= 0) || (funcName == "") {
+		return callerInfo{}
+	}
+
+	_, pkgInfo := path.Split(path.Dir(filePath))
+	res.Pkg = pkgInfo
+
+	res.File = filePath
+	if pathElems := strings.Split(filePath, "/"); len(pathElems) > 2 {
+		res.File = strings.Join(pathElems[len(pathElems)-2:], "/")
+	}
+	res.Line = line
+
+	funcNameElems := strings.Split(funcName, "/")
+	res.FuncName = funcNameElems[len(funcNameElems)-1]
+
+	return res
+}
+
+// make template from options flag
+func (l *Logger) templateFromOptions() (res string) {
+
+	orElse := func(flag bool, value string, elseValue string) string {
+		if flag {
+			return value
+		}
+		return elseValue
+	}
+
+	var parts []string
+
+	parts = append(parts, orElse(l.msec, `{{.DT.Format "2006/01/02 15:04:05.000"}}`, `{{.DT.Format "2006/01/02 15:04:05"}}`))
+	parts = append(parts, orElse(l.levelBraces, `[{{.Level}}]`, `{{.Level}}`))
+
+	if l.callerFile || l.callerFunc || l.callerPkg {
+		var callerParts []string
+		if v := orElse(l.callerFile, `{{.CallerFile}}:{{.CallerLine}}`, ""); v != "" {
+			callerParts = append(callerParts, v)
+		}
+		if v := orElse(l.callerFunc, `{{.CallerFunc}}`, ""); v != "" {
+			callerParts = append(callerParts, v)
+		}
+		if v := orElse(l.callerPkg, `{{.CallerPkg}}`, ""); v != "" {
+			callerParts = append(callerParts, v)
+		}
+		parts = append(parts, "("+strings.Join(callerParts, " ")+")")
+	}
+	parts = append(parts, "{{.Message}}")
+	return strings.Join(parts, " ")
+}
+
+// formatLevel aligns level to 5 chars
+func (l *Logger) formatLevel(lv string) string {
+
 	if lv == "" {
 		return ""
 	}
@@ -148,9 +261,10 @@ func (l *Logger) formatLevel(lv string) string {
 	if len(lv) == 4 {
 		spaces = " "
 	}
-	return " " + brace("[") + lv + brace("]") + spaces
+	return lv + spaces
 }
 
+// extractLevel parses messages with optional level prefix and returns level and the message with stripped level
 func (l *Logger) extractLevel(line string) (level, msg string) {
 	for _, lv := range levels {
 		if strings.HasPrefix(line, lv) {
@@ -196,9 +310,23 @@ func Debug(l *Logger) {
 	l.dbg = true
 }
 
-// CallerFile adds caller info with file, and line number
-func CallerFile(l *Logger) {
-	l.callerFile = true
+// Trace turn on trace + dbg mode
+func Trace(l *Logger) {
+	l.dbg = true
+	l.trace = true
+}
+
+// CallerDepth sets number of stack frame skipped for caller reporting
+func CallerDepth(n int) Option {
+	return func(l *Logger) {
+		l.callerDepth = n
+	}
+}
+
+func Format(f string) Option {
+	return func(l *Logger) {
+		l.format = f
+	}
 }
 
 // CallerFunc adds caller info with function name
@@ -211,26 +339,16 @@ func CallerPkg(l *Logger) {
 	l.callerPkg = true
 }
 
-// CallerIgnore sets packages skipped from logging caller
-func CallerIgnore(ignores ...string) Option {
-	return func(l *Logger) {
-		l.ignoredPkgCallers = ignores
-	}
-}
-
-// CallerSkip sets how many trace levels to skip.
-// by default this value is 1 , i.e. skip logger level only
-func CallerSkip(n int) Option {
-	return func(l *Logger) {
-		l.callerSkip = n
-	}
-}
-
 // LevelBraces adds [] to level
 func LevelBraces(l *Logger) {
 	l.levelBraces = true
 }
 
+// CallerFile adds caller info with file, and line number
+func CallerFile(l *Logger) {
+	l.callerFile = true
+}
+
 // Msec adds .msec to timestamp
 func Msec(l *Logger) {
 	l.msec = true