Merge pull request #898 from ploxiln/logging_refactor_2

*: internal logging package refactor

apps/nsqadmin/main.go

@@ -22,7 +22,7 @@ var (
 	config      = flagSet.String("config", "", "path to config file")
 	showVersion = flagSet.Bool("version", false, "print version string")
 
-	logLevel  = flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal)")
+	logLevel  = flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal")
 	logPrefix = flagSet.String("log-prefix", "[nsqadmin] ", "log message prefix")
 	verbose   = flagSet.Bool("verbose", false, "deprecated in favor of log-level")
 

apps/nsqd/nsqd.go

@@ -80,7 +80,7 @@ func nsqdFlagSet(opts *nsqd.Options) *flag.FlagSet {
 	flagSet.Bool("version", false, "print version string")
 	flagSet.String("config", "", "path to config file")
 
-	flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal)")
+	flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal")
 	flagSet.String("log-prefix", "[nsqd] ", "log message prefix")
 	flagSet.Bool("verbose", false, "deprecated in favor of log-level")
 

apps/nsqlookupd/nsqlookupd.go

@@ -21,7 +21,7 @@ func nsqlookupdFlagSet(opts *nsqlookupd.Options) *flag.FlagSet {
 	flagSet.String("config", "", "path to config file")
 	flagSet.Bool("version", false, "print version string")
 
-	flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal)")
+	flagSet.String("log-level", "info", "set log verbosity: debug, info, warn, error, or fatal")
 	flagSet.String("log-prefix", "[nsqlookupd] ", "log message prefix")
 	flagSet.Bool("verbose", false, "deprecated in favor of log-level")
 

internal/clusterinfo/data.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/blang/semver"
 	"github.com/nsqio/nsq/internal/http_api"
+	"github.com/nsqio/nsq/internal/lg"
 	"github.com/nsqio/nsq/internal/stringy"
 )
 
@@ -33,27 +34,22 @@ func (l ErrList) Errors() []error {
 	return l
 }
 
-type logger interface {
-	Output(maxdepth int, s string) error
-}
-
 type ClusterInfo struct {
-	log    logger
+	log    lg.AppLogFunc
 	client *http_api.Client
 }
 
-func New(log logger, client *http_api.Client) *ClusterInfo {
+func New(log lg.AppLogFunc, client *http_api.Client) *ClusterInfo {
 	return &ClusterInfo{
 		log:    log,
 		client: client,
 	}
 }
 
 func (c *ClusterInfo) logf(f string, args ...interface{}) {
-	if c.log == nil {
-		return
+	if c.log != nil {
+		c.log(lg.INFO, f, args...)
 	}
-	c.log.Output(2, fmt.Sprintf(f, args...))
 }
 
 // GetVersion returns a semver.Version object by querying /info

internal/http_api/api_response.go

@@ -8,7 +8,7 @@ import (
 	"time"
 
 	"github.com/julienschmidt/httprouter"
-	"github.com/nsqio/nsq/internal/app"
+	"github.com/nsqio/nsq/internal/lg"
 )
 
 type Decorator func(APIHandler) APIHandler
@@ -112,7 +112,7 @@ func Decorate(f APIHandler, ds ...Decorator) httprouter.Handle {
 	}
 }
 
-func Log(l app.Logger) Decorator {
+func Log(logf lg.AppLogFunc) Decorator {
 	return func(f APIHandler) APIHandler {
 		return func(w http.ResponseWriter, req *http.Request, ps httprouter.Params) (interface{}, error) {
 			start := time.Now()
@@ -122,34 +122,34 @@ func Log(l app.Logger) Decorator {
 			if e, ok := err.(Err); ok {
 				status = e.Code
 			}
-			l.Output(2, fmt.Sprintf("%d %s %s (%s) %s",
-				status, req.Method, req.URL.RequestURI(), req.RemoteAddr, elapsed))
+			logf(lg.INFO, "%d %s %s (%s) %s",
+				status, req.Method, req.URL.RequestURI(), req.RemoteAddr, elapsed)
 			return response, err
 		}
 	}
 }
 
-func LogPanicHandler(l app.Logger) func(w http.ResponseWriter, req *http.Request, p interface{}) {
+func LogPanicHandler(logf lg.AppLogFunc) func(w http.ResponseWriter, req *http.Request, p interface{}) {
 	return func(w http.ResponseWriter, req *http.Request, p interface{}) {
-		l.Output(2, fmt.Sprintf("ERROR: panic in HTTP handler - %s", p))
+		logf(lg.ERROR, "panic in HTTP handler - %s", p)
 		Decorate(func(w http.ResponseWriter, req *http.Request, ps httprouter.Params) (interface{}, error) {
 			return nil, Err{500, "INTERNAL_ERROR"}
-		}, Log(l), V1)(w, req, nil)
+		}, Log(logf), V1)(w, req, nil)
 	}
 }
 
-func LogNotFoundHandler(l app.Logger) http.Handler {
+func LogNotFoundHandler(logf lg.AppLogFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		Decorate(func(w http.ResponseWriter, req *http.Request, ps httprouter.Params) (interface{}, error) {
 			return nil, Err{404, "NOT_FOUND"}
-		}, Log(l), V1)(w, req, nil)
+		}, Log(logf), V1)(w, req, nil)
 	})
 }
 
-func LogMethodNotAllowedHandler(l app.Logger) http.Handler {
+func LogMethodNotAllowedHandler(logf lg.AppLogFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 		Decorate(func(w http.ResponseWriter, req *http.Request, ps httprouter.Params) (interface{}, error) {
 			return nil, Err{405, "METHOD_NOT_ALLOWED"}
-		}, Log(l), V1)(w, req, nil)
+		}, Log(logf), V1)(w, req, nil)
 	})
 }

internal/http_api/http_server.go

@@ -1,36 +1,35 @@
 package http_api
 
 import (
-	"fmt"
 	"log"
 	"net"
 	"net/http"
 	"strings"
 
-	"github.com/nsqio/nsq/internal/app"
+	"github.com/nsqio/nsq/internal/lg"
 )
 
 type logWriter struct {
-	app.Logger
+	logf lg.AppLogFunc
 }
 
 func (l logWriter) Write(p []byte) (int, error) {
-	l.Logger.Output(2, string(p))
+	l.logf(lg.WARN, "%s", string(p))
 	return len(p), nil
 }
 
-func Serve(listener net.Listener, handler http.Handler, proto string, l app.Logger) {
-	l.Output(2, fmt.Sprintf("%s: listening on %s", proto, listener.Addr()))
+func Serve(listener net.Listener, handler http.Handler, proto string, logf lg.AppLogFunc) {
+	logf(lg.INFO, "%s: listening on %s", proto, listener.Addr())
 
 	server := &http.Server{
 		Handler:  handler,
-		ErrorLog: log.New(logWriter{l}, "", 0),
+		ErrorLog: log.New(logWriter{logf}, "", 0),
 	}
 	err := server.Serve(listener)
 	// theres no direct way to detect this error because it is not exposed
 	if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
-		l.Output(2, fmt.Sprintf("ERROR: http.Serve() - %s", err))
+		logf(lg.ERROR, "http.Serve() - %s", err)
 	}
 
-	l.Output(2, fmt.Sprintf("%s: closing %s", proto, listener.Addr()))
+	logf(lg.INFO, "%s: closing %s", proto, listener.Addr())
 }

internal/lg/lg.go

@@ -0,0 +1,75 @@
+// short for "log"
+package lg
+
+import (
+	"fmt"
+	"strings"
+)
+
+type LogLevel int
+
+const (
+	DEBUG = LogLevel(1)
+	INFO  = LogLevel(2)
+	WARN  = LogLevel(3)
+	ERROR = LogLevel(4)
+	FATAL = LogLevel(5)
+)
+
+type AppLogFunc func(lvl LogLevel, f string, args ...interface{})
+
+type Logger interface {
+	Output(maxdepth int, s string) error
+}
+
+type NilLogger struct{}
+
+func (l NilLogger) Output(maxdepth int, s string) error {
+	return nil
+}
+
+func (l LogLevel) String() string {
+	switch l {
+	case 1:
+		return "DEBUG"
+	case 2:
+		return "INFO"
+	case 3:
+		return "WARNING"
+	case 4:
+		return "ERROR"
+	case 5:
+		return "FATAL"
+	}
+	panic("invalid LogLevel")
+}
+
+func ParseLogLevel(levelstr string, verbose bool) (LogLevel, error) {
+	lvl := INFO
+
+	switch strings.ToLower(levelstr) {
+	case "debug":
+		lvl = DEBUG
+	case "info":
+		lvl = INFO
+	case "warn":
+		lvl = WARN
+	case "error":
+		lvl = ERROR
+	case "fatal":
+		lvl = FATAL
+	default:
+		return lvl, fmt.Errorf("invalid log-level '%s'", levelstr)
+	}
+	if verbose {
+		lvl = DEBUG
+	}
+	return lvl, nil
+}
+
+func Logf(logger Logger, cfgLevel LogLevel, msgLevel LogLevel, f string, args ...interface{}) {
+	if cfgLevel > msgLevel {
+		return
+	}
+	logger.Output(3, fmt.Sprintf(msgLevel.String()+": "+f, args...))
+}

internal/lg/lg_test.go

@@ -0,0 +1,109 @@
+package lg
+
+import (
+	"log"
+	"os"
+	"testing"
+
+	"github.com/nsqio/nsq/internal/test"
+)
+
+type options struct {
+	LogLevel string `flag:"log-level"`
+	Verbose  bool   `flag:"verbose"` // for backwards compatibility
+	Logger   Logger
+	logLevel LogLevel // private, not really an option
+}
+
+func newOptions() *options {
+	return &options{
+		LogLevel: "info",
+	}
+}
+
+type app struct {
+	opts *options
+}
+
+func (n *app) logf(level LogLevel, f string, args ...interface{}) {
+	Logf(n.opts.Logger, n.opts.logLevel, level, f, args)
+}
+
+func newApp(opts *options) *app {
+	if opts.Logger == nil {
+		opts.Logger = log.New(os.Stderr, "[app] ", log.Ldate|log.Ltime|log.Lmicroseconds)
+	}
+	n := &app{
+		opts: opts,
+	}
+
+	var err error
+	opts.logLevel, err = ParseLogLevel(opts.LogLevel, opts.Verbose)
+	if err != nil {
+		n.logf(FATAL, "%s", err)
+		os.Exit(1)
+	}
+
+	n.logf(INFO, "app 0.1")
+	return n
+}
+
+type mockLogger struct {
+	Count int
+}
+
+func (l *mockLogger) Output(maxdepth int, s string) error {
+	l.Count++
+	return nil
+}
+
+func TestLogging(t *testing.T) {
+	logger := &mockLogger{}
+	opts := newOptions()
+	opts.Logger = logger
+
+	// Test only fatal get through
+	opts.LogLevel = "FaTaL"
+	nsqd := newApp(opts)
+	logger.Count = 0
+	for i := 1; i <= 5; i++ {
+		nsqd.logf(LogLevel(i), "Test")
+	}
+	test.Equal(t, 1, logger.Count)
+
+	// Test only warnings or higher get through
+	opts.LogLevel = "WARN"
+	nsqd = newApp(opts)
+	logger.Count = 0
+	for i := 1; i <= 5; i++ {
+		nsqd.logf(LogLevel(i), "Test")
+	}
+	test.Equal(t, 3, logger.Count)
+
+	// Test everything gets through
+	opts.LogLevel = "debuG"
+	nsqd = newApp(opts)
+	logger.Count = 0
+	for i := 1; i <= 5; i++ {
+		nsqd.logf(LogLevel(i), "Test")
+	}
+	test.Equal(t, 5, logger.Count)
+
+	// Test everything gets through with verbose = true
+	opts.LogLevel = "fatal"
+	opts.Verbose = true
+	nsqd = newApp(opts)
+	logger.Count = 0
+	for i := 1; i <= 5; i++ {
+		nsqd.logf(LogLevel(i), "Test")
+	}
+	test.Equal(t, 5, logger.Count)
+}
+
+func TestNoLogger(t *testing.T) {
+	opts := newOptions()
+	opts.Logger = NilLogger{}
+	app := newApp(opts)
+
+	app.logf(ERROR, "should never be logged")
+}