From 4a88d155292c0648cef2fd652722a229749258cf Mon Sep 17 00:00:00 2001 From: Pierce Lopez Date: Sat, 20 May 2017 02:16:38 -0400 Subject: [PATCH 1/5] nsqd: a few misc logging line cleanups --- nsqd/client_v2.go | 3 +-- nsqd/nsqd.go | 2 +- nsqd/protocol_v2.go | 3 +-- 3 files changed, 3 insertions(+), 5 deletions(-) diff --git a/nsqd/client_v2.go b/nsqd/client_v2.go index c1e93a48a..68025b9be 100644 --- a/nsqd/client_v2.go +++ b/nsqd/client_v2.go @@ -303,8 +303,7 @@ func (c *clientV2) IsReadyForMessages() bool { readyCount := atomic.LoadInt64(&c.ReadyCount) inFlightCount := atomic.LoadInt64(&c.InFlightCount) - c.ctx.nsqd.logf(LOG_DEBUG, "[%s] state rdy: %4d inflt: %4d", - c, readyCount, inFlightCount) + c.ctx.nsqd.logf(LOG_DEBUG, "[%s] state rdy: %4d inflt: %4d", c, readyCount, inFlightCount) if inFlightCount >= readyCount || readyCount <= 0 { return false diff --git a/nsqd/nsqd.go b/nsqd/nsqd.go index 2aa0afa2c..4cbc4ae7d 100644 --- a/nsqd/nsqd.go +++ b/nsqd/nsqd.go @@ -120,7 +120,7 @@ func New(opts *Options) *NSQD { var port string _, port, err = net.SplitHostPort(opts.HTTPAddress) if err != nil { - n.logf(LOG_ERROR, "failed to parse HTTP address (%s) - %s", opts.HTTPAddress, err) + n.logf(LOG_FATAL, "failed to parse HTTP address (%s) - %s", opts.HTTPAddress, err) os.Exit(1) } statsdHostKey := statsd.HostKey(net.JoinHostPort(opts.BroadcastAddress, port)) diff --git a/nsqd/protocol_v2.go b/nsqd/protocol_v2.go index 374810596..611d5f167 100644 --- a/nsqd/protocol_v2.go +++ b/nsqd/protocol_v2.go @@ -122,8 +122,7 @@ func (p *protocolV2) IOLoop(conn net.Conn) error { } func (p *protocolV2) SendMessage(client *clientV2, msg *Message, buf *bytes.Buffer) error { - p.ctx.nsqd.logf(LOG_DEBUG, "PROTOCOL(V2): writing msg(%s) to client(%s) - %s", - msg.ID, client, msg.Body) + p.ctx.nsqd.logf(LOG_DEBUG, "PROTOCOL(V2): writing msg(%s) to client(%s) - %s", msg.ID, client, msg.Body) buf.Reset() _, err := msg.WriteTo(buf) From a2d21469288bf7f24863875b19056b4e5ffda5c7 Mon Sep 17 00:00:00 2001 From: Pierce Lopez Date: Sat, 20 May 2017 02:17:57 -0400 Subject: [PATCH 2/5] nsq*: clean up, regularize logging Options minor fix for --log-level flag help text must set opts before logging errors in New() re-order log stuff in Options structs treat logLevel the same in nsqd, nsqlookupd, nsqadmin Fix tests: multiple nsqlookupds need their own Options structs, now that nsqlookupd has logLevel in its Options. Otherwise the race detector complains when one of the nsqlookupds writes the derived int logLevel while another reads it for logging. --- apps/nsqadmin/main.go | 2 +- apps/nsqd/nsqd.go | 2 +- apps/nsqlookupd/nsqlookupd.go | 2 +- nsqadmin/http_test.go | 7 +++++-- nsqadmin/nsqadmin.go | 3 +-- nsqadmin/options.go | 5 ++--- nsqd/http_test.go | 7 +++++-- nsqd/nsqd.go | 5 ++--- nsqd/nsqd_test.go | 10 +++++++--- nsqd/options.go | 15 +++++++-------- nsqlookupd/logger.go | 2 +- nsqlookupd/nsqlookupd.go | 5 ++--- nsqlookupd/options.go | 4 ++-- 13 files changed, 37 insertions(+), 32 deletions(-) diff --git a/apps/nsqadmin/main.go b/apps/nsqadmin/main.go index cd2b02e50..9a67191e1 100644 --- a/apps/nsqadmin/main.go +++ b/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") diff --git a/apps/nsqd/nsqd.go b/apps/nsqd/nsqd.go index 5171f309e..575bbdfd2 100644 --- a/apps/nsqd/nsqd.go +++ b/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") diff --git a/apps/nsqlookupd/nsqlookupd.go b/apps/nsqlookupd/nsqlookupd.go index f96881692..c70a48fec 100644 --- a/apps/nsqlookupd/nsqlookupd.go +++ b/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") diff --git a/nsqadmin/http_test.go b/nsqadmin/http_test.go index 9e7fd0c8a..d5389bd0c 100644 --- a/nsqadmin/http_test.go +++ b/nsqadmin/http_test.go @@ -529,9 +529,12 @@ func TestHTTPconfig(t *testing.T) { lopts := nsqlookupd.NewOptions() lopts.Logger = test.NewTestLogger(t) - _, _, lookupd1 := mustStartNSQLookupd(lopts) + + lopts1 := *lopts + _, _, lookupd1 := mustStartNSQLookupd(&lopts1) defer lookupd1.Exit() - _, _, lookupd2 := mustStartNSQLookupd(lopts) + lopts2 := *lopts + _, _, lookupd2 := mustStartNSQLookupd(&lopts2) defer lookupd2.Exit() url := fmt.Sprintf("http://%s/config/nsqlookupd_http_addresses", nsqadmin1.RealHTTPAddr()) diff --git a/nsqadmin/nsqadmin.go b/nsqadmin/nsqadmin.go index 0e30ab2d0..77119e4ae 100644 --- a/nsqadmin/nsqadmin.go +++ b/nsqadmin/nsqadmin.go @@ -37,6 +37,7 @@ func New(opts *Options) *NSQAdmin { n := &NSQAdmin{ notifications: make(chan *AdminAction), } + n.swapOpts(opts) // check log-level is valid and translate to int opts.logLevel = n.logLevelFromString(opts.LogLevel) @@ -45,8 +46,6 @@ func New(opts *Options) *NSQAdmin { os.Exit(1) } - n.swapOpts(opts) - if len(opts.NSQDHTTPAddresses) == 0 && len(opts.NSQLookupdHTTPAddresses) == 0 { n.logf(LOG_FATAL, "--nsqd-http-address or --lookupd-http-address required.") os.Exit(1) diff --git a/nsqadmin/options.go b/nsqadmin/options.go index c44990e18..39652d680 100644 --- a/nsqadmin/options.go +++ b/nsqadmin/options.go @@ -6,9 +6,10 @@ import ( type Options struct { LogLevel string `flag:"log-level"` - logLevel int LogPrefix string `flag:"log-prefix"` Verbose bool `flag:"verbose"` // for backwards compatibility + Logger Logger + logLevel int // private, not really an option HTTPAddress string `flag:"http-address"` @@ -35,8 +36,6 @@ type Options struct { AllowConfigFromCIDR string `flag:"allow-config-from-cidr"` NotificationHTTPEndpoint string `flag:"notification-http-endpoint"` - - Logger Logger } func NewOptions() *Options { diff --git a/nsqd/http_test.go b/nsqd/http_test.go index f0a950f61..7bcb78f06 100644 --- a/nsqd/http_test.go +++ b/nsqd/http_test.go @@ -513,9 +513,12 @@ func TestHTTPgetStatusText(t *testing.T) { func TestHTTPconfig(t *testing.T) { lopts := nsqlookupd.NewOptions() lopts.Logger = test.NewTestLogger(t) - _, _, lookupd1 := mustStartNSQLookupd(lopts) + + lopts1 := *lopts + _, _, lookupd1 := mustStartNSQLookupd(&lopts1) defer lookupd1.Exit() - _, _, lookupd2 := mustStartNSQLookupd(lopts) + lopts2 := *lopts + _, _, lookupd2 := mustStartNSQLookupd(&lopts2) defer lookupd2.Exit() opts := NewOptions() diff --git a/nsqd/nsqd.go b/nsqd/nsqd.go index 4cbc4ae7d..c7ba3b768 100644 --- a/nsqd/nsqd.go +++ b/nsqd/nsqd.go @@ -89,6 +89,8 @@ func New(opts *Options) *NSQD { ci: clusterinfo.New(opts.Logger, http_api.NewClient(nil, opts.HTTPClientConnectTimeout, opts.HTTPClientRequestTimeout)), dl: dirlock.New(dataPath), } + n.swapOpts(opts) + n.errValue.Store(errStore{}) // check log-level is valid and translate to int opts.logLevel = n.logLevelFromString(opts.LogLevel) @@ -97,9 +99,6 @@ func New(opts *Options) *NSQD { os.Exit(1) } - n.swapOpts(opts) - n.errValue.Store(errStore{}) - err := n.dl.Lock() if err != nil { n.logf(LOG_FATAL, "--data-path=%s in use (possibly by another instance of nsqd)", dataPath) diff --git a/nsqd/nsqd_test.go b/nsqd/nsqd_test.go index 305c28662..e64a1e556 100644 --- a/nsqd/nsqd_test.go +++ b/nsqd/nsqd_test.go @@ -351,11 +351,15 @@ func mustStartNSQLookupd(opts *nsqlookupd.Options) (*net.TCPAddr, *net.TCPAddr, func TestReconfigure(t *testing.T) { lopts := nsqlookupd.NewOptions() lopts.Logger = test.NewTestLogger(t) - _, _, lookupd1 := mustStartNSQLookupd(lopts) + + lopts1 := *lopts + _, _, lookupd1 := mustStartNSQLookupd(&lopts1) defer lookupd1.Exit() - _, _, lookupd2 := mustStartNSQLookupd(lopts) + lopts2 := *lopts + _, _, lookupd2 := mustStartNSQLookupd(&lopts2) defer lookupd2.Exit() - _, _, lookupd3 := mustStartNSQLookupd(lopts) + lopts3 := *lopts + _, _, lookupd3 := mustStartNSQLookupd(&lopts3) defer lookupd3.Exit() opts := NewOptions() diff --git a/nsqd/options.go b/nsqd/options.go index b4e744219..3cfe99aee 100644 --- a/nsqd/options.go +++ b/nsqd/options.go @@ -12,11 +12,13 @@ import ( type Options struct { // basic options - ID int64 `flag:"node-id" cfg:"id"` - LogLevel string `flag:"log-level"` - logLevel int - LogPrefix string `flag:"log-prefix"` - Verbose bool `flag:"verbose"` // for backwards compatibility + ID int64 `flag:"node-id" cfg:"id"` + LogLevel string `flag:"log-level"` + LogPrefix string `flag:"log-prefix"` + Verbose bool `flag:"verbose"` // for backwards compatibility + Logger Logger + logLevel int // private, not really an option + TCPAddress string `flag:"tcp-address"` HTTPAddress string `flag:"http-address"` HTTPSAddress string `flag:"https-address"` @@ -75,8 +77,6 @@ type Options struct { DeflateEnabled bool `flag:"deflate"` MaxDeflateLevel int `flag:"max-deflate-level"` SnappyEnabled bool `flag:"snappy"` - - Logger Logger } func NewOptions() *Options { @@ -93,7 +93,6 @@ func NewOptions() *Options { ID: defaultID, LogPrefix: "[nsqd] ", LogLevel: "info", - logLevel: 2, TCPAddress: "0.0.0.0:4150", HTTPAddress: "0.0.0.0:4151", diff --git a/nsqlookupd/logger.go b/nsqlookupd/logger.go index e3aad9717..c76532b6a 100644 --- a/nsqlookupd/logger.go +++ b/nsqlookupd/logger.go @@ -50,7 +50,7 @@ func (n *NSQLookupd) logf(level int, f string, args ...interface{}) { levelString = "FATAL" } - if level >= n.logLevel || n.opts.Verbose { + if level >= n.opts.logLevel || n.opts.Verbose { n.opts.Logger.Output(2, fmt.Sprintf(levelString+": "+f, args...)) } } diff --git a/nsqlookupd/nsqlookupd.go b/nsqlookupd/nsqlookupd.go index c5f661bfa..7b10a3440 100644 --- a/nsqlookupd/nsqlookupd.go +++ b/nsqlookupd/nsqlookupd.go @@ -19,7 +19,6 @@ type NSQLookupd struct { httpListener net.Listener waitGroup util.WaitGroupWrapper DB *RegistrationDB - logLevel int } func New(opts *Options) *NSQLookupd { @@ -32,8 +31,8 @@ func New(opts *Options) *NSQLookupd { } // check log-level is valid and translate to int - n.logLevel = n.logLevelFromString(opts.LogLevel) - if n.logLevel == -1 { + n.opts.logLevel = n.logLevelFromString(opts.LogLevel) + if n.opts.logLevel == -1 { n.logf(LOG_FATAL, "log level '%s' should be one of: debug, info, warn, error, or fatal", opts.LogLevel) os.Exit(1) } diff --git a/nsqlookupd/options.go b/nsqlookupd/options.go index 57ebdaf7f..2217111a0 100644 --- a/nsqlookupd/options.go +++ b/nsqlookupd/options.go @@ -10,6 +10,8 @@ type Options struct { LogLevel string `flag:"log-level"` LogPrefix string `flag:"log-prefix"` Verbose bool `flag:"verbose"` // for backwards compatibility + Logger Logger + logLevel int // private, not really an option TCPAddress string `flag:"tcp-address"` HTTPAddress string `flag:"http-address"` @@ -17,8 +19,6 @@ type Options struct { InactiveProducerTimeout time.Duration `flag:"inactive-producer-timeout"` TombstoneLifetime time.Duration `flag:"tombstone-lifetime"` - - Logger Logger } func NewOptions() *Options { From 60c90a8b341bee1432efa1e95364fe0fd3d012d4 Mon Sep 17 00:00:00 2001 From: Pierce Lopez Date: Sat, 20 May 2017 12:31:55 -0400 Subject: [PATCH 3/5] tests: more delay in TestClientMsgTimeout --- nsqd/protocol_v2_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/nsqd/protocol_v2_test.go b/nsqd/protocol_v2_test.go index 1330b8fe3..a6229f721 100644 --- a/nsqd/protocol_v2_test.go +++ b/nsqd/protocol_v2_test.go @@ -1362,7 +1362,7 @@ func TestClientMsgTimeout(t *testing.T) { _, err = nsq.Ready(0).WriteTo(conn) test.Nil(t, err) - time.Sleep(1100 * time.Millisecond) + time.Sleep(1150 * time.Millisecond) test.Equal(t, 1, int(atomic.LoadUint64(&ch.timeoutCount))) test.Equal(t, 0, int(atomic.LoadUint64(&ch.requeueCount))) From 2b4a6104d2f69aa15e285503f31a2ab0faecb7df Mon Sep 17 00:00:00 2001 From: Pierce Lopez Date: Sat, 20 May 2017 02:49:59 -0400 Subject: [PATCH 4/5] new internal/lg/ logging package for nsqd nsqlookupd nsqadmin introduce LogLevel type NilLogger for disabling logging consolidate LogLevel tests into internal/lg/ consolidate TestNoLogger --- internal/lg/lg.go | 73 +++++++++++++++++++++++ internal/lg/lg_test.go | 109 ++++++++++++++++++++++++++++++++++ nsqadmin/http.go | 9 ++- nsqadmin/logger.go | 55 +++-------------- nsqadmin/nsqadmin.go | 9 +-- nsqadmin/nsqadmin_test.go | 81 ++----------------------- nsqadmin/options.go | 4 +- nsqd/http.go | 9 ++- nsqd/logger.go | 55 +++-------------- nsqd/nsqd.go | 11 ++-- nsqd/nsqd_test.go | 57 ------------------ nsqd/options.go | 4 +- nsqlookupd/logger.go | 55 +++-------------- nsqlookupd/nsqlookupd.go | 9 +-- nsqlookupd/nsqlookupd_test.go | 70 ---------------------- nsqlookupd/options.go | 4 +- 16 files changed, 246 insertions(+), 368 deletions(-) create mode 100644 internal/lg/lg.go create mode 100644 internal/lg/lg_test.go diff --git a/internal/lg/lg.go b/internal/lg/lg.go new file mode 100644 index 000000000..9c8bc925e --- /dev/null +++ b/internal/lg/lg.go @@ -0,0 +1,73 @@ +// 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 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...)) +} diff --git a/internal/lg/lg_test.go b/internal/lg/lg_test.go new file mode 100644 index 000000000..ec93ec610 --- /dev/null +++ b/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") +} diff --git a/nsqadmin/http.go b/nsqadmin/http.go index 8ed336d59..bcd4430e2 100644 --- a/nsqadmin/http.go +++ b/nsqadmin/http.go @@ -19,6 +19,7 @@ import ( "github.com/julienschmidt/httprouter" "github.com/nsqio/nsq/internal/clusterinfo" "github.com/nsqio/nsq/internal/http_api" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/protocol" "github.com/nsqio/nsq/internal/version" ) @@ -734,14 +735,12 @@ func (s *httpServer) doConfig(w http.ResponseWriter, req *http.Request, ps httpr } case "log_level": logLevelStr := string(body) - logLevelInt := s.ctx.nsqadmin.logLevelFromString(logLevelStr) - if logLevelInt == -1 { + logLevel, err := lg.ParseLogLevel(logLevelStr, opts.Verbose) + if err != nil { return nil, http_api.Err{400, "INVALID_VALUE"} } - - // save the log level opts.LogLevel = logLevelStr - opts.logLevel = logLevelInt + opts.logLevel = logLevel default: return nil, http_api.Err{400, "INVALID_OPTION"} } diff --git a/nsqadmin/logger.go b/nsqadmin/logger.go index 9455f33d4..90c123ba1 100644 --- a/nsqadmin/logger.go +++ b/nsqadmin/logger.go @@ -1,57 +1,20 @@ package nsqadmin import ( - "fmt" - "strings" + "github.com/nsqio/nsq/internal/lg" ) -type Logger interface { - Output(maxdepth int, s string) error -} +type Logger lg.Logger const ( - LOG_DEBUG = 1 - LOG_INFO = 2 - LOG_WARN = 3 - LOG_ERROR = 4 - LOG_FATAL = 5 + LOG_DEBUG = lg.DEBUG + LOG_INFO = lg.INFO + LOG_WARN = lg.WARN + LOG_ERROR = lg.ERROR + LOG_FATAL = lg.FATAL ) -func (n *NSQAdmin) logLevelFromString(level string) int { - // check log-level is valid and translate to int - switch strings.ToLower(level) { - case "debug": - return LOG_DEBUG - case "info": - return LOG_INFO - case "warn": - return LOG_WARN - case "error": - return LOG_ERROR - case "fatal": - return LOG_FATAL - default: - return -1 - } -} - -func (n *NSQAdmin) logf(level int, f string, args ...interface{}) { - levelString := "INFO" - switch level { - case LOG_DEBUG: - levelString = "DEBUG" - case LOG_INFO: - levelString = "INFO" - case LOG_WARN: - levelString = "WARNING" - case LOG_ERROR: - levelString = "ERROR" - case LOG_FATAL: - levelString = "FATAL" - } - +func (n *NSQAdmin) logf(level lg.LogLevel, f string, args ...interface{}) { opts := n.getOpts() - if level >= opts.logLevel || opts.Verbose { - n.getOpts().Logger.Output(2, fmt.Sprintf(levelString+": "+f, args...)) - } + lg.Logf(opts.Logger, opts.logLevel, level, f, args...) } diff --git a/nsqadmin/nsqadmin.go b/nsqadmin/nsqadmin.go index 77119e4ae..b1ccba800 100644 --- a/nsqadmin/nsqadmin.go +++ b/nsqadmin/nsqadmin.go @@ -15,6 +15,7 @@ import ( "sync/atomic" "github.com/nsqio/nsq/internal/http_api" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/util" "github.com/nsqio/nsq/internal/version" ) @@ -39,10 +40,10 @@ func New(opts *Options) *NSQAdmin { } n.swapOpts(opts) - // check log-level is valid and translate to int - opts.logLevel = n.logLevelFromString(opts.LogLevel) - if opts.logLevel == -1 { - n.logf(LOG_FATAL, "log level '%s' should be one of: debug, info, warn, error, or fatal", opts.LogLevel) + var err error + opts.logLevel, err = lg.ParseLogLevel(opts.LogLevel, opts.Verbose) + if err != nil { + n.logf(LOG_FATAL, "%s", err) os.Exit(1) } diff --git a/nsqadmin/nsqadmin_test.go b/nsqadmin/nsqadmin_test.go index 36a4e3e1b..c9651ca83 100644 --- a/nsqadmin/nsqadmin_test.go +++ b/nsqadmin/nsqadmin_test.go @@ -10,24 +10,15 @@ import ( "os/exec" "testing" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/test" "github.com/nsqio/nsq/nsqd" ) -func TestNoLogger(t *testing.T) { - opts := NewOptions() - opts.Logger = nil - opts.HTTPAddress = "127.0.0.1:0" - opts.NSQLookupdHTTPAddresses = []string{"127.0.0.1:4161"} - nsqadmin := New(opts) - - nsqadmin.logf(LOG_ERROR, "should never be logged") -} - func TestNeitherNSQDAndNSQLookup(t *testing.T) { if os.Getenv("BE_CRASHER") == "1" { opts := NewOptions() - opts.Logger = nil + opts.Logger = lg.NilLogger{} opts.HTTPAddress = "127.0.0.1:0" New(opts) return @@ -45,7 +36,7 @@ func TestNeitherNSQDAndNSQLookup(t *testing.T) { func TestBothNSQDAndNSQLookup(t *testing.T) { if os.Getenv("BE_CRASHER") == "1" { opts := NewOptions() - opts.Logger = nil + opts.Logger = lg.NilLogger{} opts.HTTPAddress = "127.0.0.1:0" opts.NSQLookupdHTTPAddresses = []string{"127.0.0.1:4161"} opts.NSQDHTTPAddresses = []string{"127.0.0.1:4151"} @@ -115,13 +106,9 @@ func mustStartNSQD(opts *nsqd.Options) (*net.TCPAddr, *net.TCPAddr, *nsqd.NSQD) func TestCrashingLogger(t *testing.T) { if os.Getenv("BE_CRASHER") == "1" { // Test invalid log level causes error - nsqdOpts := nsqd.NewOptions() - _, _, nsqd := mustStartNSQD(nsqdOpts) - defer os.RemoveAll(nsqdOpts.DataPath) - defer nsqd.Exit() - opts := NewOptions() opts.LogLevel = "bad" + opts.NSQLookupdHTTPAddresses = []string{"127.0.0.1:4161"} _ = New(opts) return } @@ -133,63 +120,3 @@ func TestCrashingLogger(t *testing.T) { } t.Fatalf("process ran with err %v, want exit status 1", err) } - -type mockLogger struct { - Count int -} - -func (l *mockLogger) Output(maxdepth int, s string) error { - l.Count++ - return nil -} - -func TestLogging(t *testing.T) { - nsqdOpts := nsqd.NewOptions() - _, nsqdHTTPAddr, nsqd := mustStartNSQD(nsqdOpts) - defer os.RemoveAll(nsqdOpts.DataPath) - defer nsqd.Exit() - - logger := &mockLogger{} - - opts := NewOptions() - opts.HTTPAddress = "127.0.0.1:0" - opts.NSQDHTTPAddresses = []string{nsqdHTTPAddr.String()} - opts.Logger = logger - - // Test only fatal get through - opts.LogLevel = "FaTaL" - nsqadmin1 := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqadmin1.logf(i, "Test") - } - test.Equal(t, 1, logger.Count) - - // Test only warnings or higher get through - opts.LogLevel = "WARN" - nsqadmin2 := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqadmin2.logf(i, "Test") - } - test.Equal(t, 3, logger.Count) - - // Test everything gets through - opts.LogLevel = "debuG" - nsqadmin3 := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqadmin3.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) - - // Test everything gets through with verbose = true - opts.LogLevel = "fatal" - opts.Verbose = true - nsqadmin4 := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqadmin4.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) -} diff --git a/nsqadmin/options.go b/nsqadmin/options.go index 39652d680..07c1b21c1 100644 --- a/nsqadmin/options.go +++ b/nsqadmin/options.go @@ -2,6 +2,8 @@ package nsqadmin import ( "time" + + "github.com/nsqio/nsq/internal/lg" ) type Options struct { @@ -9,7 +11,7 @@ type Options struct { LogPrefix string `flag:"log-prefix"` Verbose bool `flag:"verbose"` // for backwards compatibility Logger Logger - logLevel int // private, not really an option + logLevel lg.LogLevel // private, not really an option HTTPAddress string `flag:"http-address"` diff --git a/nsqd/http.go b/nsqd/http.go index 7071e4341..ff1e2d1fe 100644 --- a/nsqd/http.go +++ b/nsqd/http.go @@ -19,6 +19,7 @@ import ( "github.com/julienschmidt/httprouter" "github.com/nsqio/nsq/internal/http_api" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/protocol" "github.com/nsqio/nsq/internal/version" ) @@ -609,14 +610,12 @@ func (s *httpServer) doConfig(w http.ResponseWriter, req *http.Request, ps httpr } case "log_level": logLevelStr := string(body) - logLevelInt := s.ctx.nsqd.logLevelFromString(logLevelStr) - if logLevelInt == -1 { + logLevel, err := lg.ParseLogLevel(logLevelStr, opts.Verbose) + if err != nil { return nil, http_api.Err{400, "INVALID_VALUE"} } - - // save the log level opts.LogLevel = logLevelStr - opts.logLevel = logLevelInt + opts.logLevel = logLevel case "verbose": err := json.Unmarshal(body, &opts.Verbose) if err != nil { diff --git a/nsqd/logger.go b/nsqd/logger.go index f43090809..51ac28db7 100644 --- a/nsqd/logger.go +++ b/nsqd/logger.go @@ -1,57 +1,20 @@ package nsqd import ( - "fmt" - "strings" + "github.com/nsqio/nsq/internal/lg" ) -type Logger interface { - Output(maxdepth int, s string) error -} +type Logger lg.Logger const ( - LOG_DEBUG = 1 - LOG_INFO = 2 - LOG_WARN = 3 - LOG_ERROR = 4 - LOG_FATAL = 5 + LOG_DEBUG = lg.DEBUG + LOG_INFO = lg.INFO + LOG_WARN = lg.WARN + LOG_ERROR = lg.ERROR + LOG_FATAL = lg.FATAL ) -func (n *NSQD) logLevelFromString(level string) int { - // check log-level is valid and translate to int - switch strings.ToLower(level) { - case "debug": - return LOG_DEBUG - case "info": - return LOG_INFO - case "warn": - return LOG_WARN - case "error": - return LOG_ERROR - case "fatal": - return LOG_FATAL - default: - return -1 - } -} - -func (n *NSQD) logf(level int, f string, args ...interface{}) { - levelString := "INFO" - switch level { - case LOG_DEBUG: - levelString = "DEBUG" - case LOG_INFO: - levelString = "INFO" - case LOG_WARN: - levelString = "WARNING" - case LOG_ERROR: - levelString = "ERROR" - case LOG_FATAL: - levelString = "FATAL" - } - +func (n *NSQD) logf(level lg.LogLevel, f string, args ...interface{}) { opts := n.getOpts() - if level >= opts.logLevel || opts.Verbose { - n.getOpts().Logger.Output(2, fmt.Sprintf(levelString+": "+f, args...)) - } + lg.Logf(opts.Logger, opts.logLevel, level, f, args...) } diff --git a/nsqd/nsqd.go b/nsqd/nsqd.go index c7ba3b768..cb363be39 100644 --- a/nsqd/nsqd.go +++ b/nsqd/nsqd.go @@ -22,6 +22,7 @@ import ( "github.com/nsqio/nsq/internal/clusterinfo" "github.com/nsqio/nsq/internal/dirlock" "github.com/nsqio/nsq/internal/http_api" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/protocol" "github.com/nsqio/nsq/internal/statsd" "github.com/nsqio/nsq/internal/util" @@ -92,14 +93,14 @@ func New(opts *Options) *NSQD { n.swapOpts(opts) n.errValue.Store(errStore{}) - // check log-level is valid and translate to int - opts.logLevel = n.logLevelFromString(opts.LogLevel) - if opts.logLevel == -1 { - n.logf(LOG_FATAL, "log level '%s' should be one of: debug, info, warn, error, or fatal", opts.LogLevel) + var err error + opts.logLevel, err = lg.ParseLogLevel(opts.LogLevel, opts.Verbose) + if err != nil { + n.logf(LOG_FATAL, "%s", err) os.Exit(1) } - err := n.dl.Lock() + err = n.dl.Lock() if err != nil { n.logf(LOG_FATAL, "--data-path=%s in use (possibly by another instance of nsqd)", dataPath) os.Exit(1) diff --git a/nsqd/nsqd_test.go b/nsqd/nsqd_test.go index e64a1e556..4e1774642 100644 --- a/nsqd/nsqd_test.go +++ b/nsqd/nsqd_test.go @@ -536,60 +536,3 @@ func TestCrashingLogger(t *testing.T) { } t.Fatalf("process ran with err %v, want exit status 1", err) } - -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 := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqd.logf(i, "Test") - } - test.Equal(t, 1, logger.Count) - nsqd.Exit() - - // Test only warnings or higher get through - opts.LogLevel = "WARN" - nsqd = New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqd.logf(i, "Test") - } - test.Equal(t, 3, logger.Count) - nsqd.Exit() - - // Test everything gets through - opts.LogLevel = "debuG" - nsqd = New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqd.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) - nsqd.Exit() - - // Test everything gets through with verbose = true - opts.LogLevel = "fatal" - nsqd = New(opts) - logger.Count = 0 - opts.Verbose = true - for i := 1; i <= 5; i++ { - nsqd.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) - nsqd.Exit() - -} diff --git a/nsqd/options.go b/nsqd/options.go index 3cfe99aee..ee461edb9 100644 --- a/nsqd/options.go +++ b/nsqd/options.go @@ -8,6 +8,8 @@ import ( "log" "os" "time" + + "github.com/nsqio/nsq/internal/lg" ) type Options struct { @@ -17,7 +19,7 @@ type Options struct { LogPrefix string `flag:"log-prefix"` Verbose bool `flag:"verbose"` // for backwards compatibility Logger Logger - logLevel int // private, not really an option + logLevel lg.LogLevel // private, not really an option TCPAddress string `flag:"tcp-address"` HTTPAddress string `flag:"http-address"` diff --git a/nsqlookupd/logger.go b/nsqlookupd/logger.go index c76532b6a..f3e91a8c3 100644 --- a/nsqlookupd/logger.go +++ b/nsqlookupd/logger.go @@ -1,56 +1,19 @@ package nsqlookupd import ( - "fmt" - "strings" + "github.com/nsqio/nsq/internal/lg" ) -type Logger interface { - Output(maxdepth int, s string) error -} +type Logger lg.Logger const ( - LOG_DEBUG = 1 - LOG_INFO = 2 - LOG_WARN = 3 - LOG_ERROR = 4 - LOG_FATAL = 5 + LOG_DEBUG = lg.DEBUG + LOG_INFO = lg.INFO + LOG_WARN = lg.WARN + LOG_ERROR = lg.ERROR + LOG_FATAL = lg.FATAL ) -func (n *NSQLookupd) logLevelFromString(level string) int { - // check log-level is valid and translate to int - switch strings.ToLower(level) { - case "debug": - return LOG_DEBUG - case "info": - return LOG_INFO - case "warn": - return LOG_WARN - case "error": - return LOG_ERROR - case "fatal": - return LOG_FATAL - default: - return -1 - } -} - -func (n *NSQLookupd) logf(level int, f string, args ...interface{}) { - levelString := "INFO" - switch level { - case LOG_DEBUG: - levelString = "DEBUG" - case LOG_INFO: - levelString = "INFO" - case LOG_WARN: - levelString = "WARNING" - case LOG_ERROR: - levelString = "ERROR" - case LOG_FATAL: - levelString = "FATAL" - } - - if level >= n.opts.logLevel || n.opts.Verbose { - n.opts.Logger.Output(2, fmt.Sprintf(levelString+": "+f, args...)) - } +func (n *NSQLookupd) logf(level lg.LogLevel, f string, args ...interface{}) { + lg.Logf(n.opts.Logger, n.opts.logLevel, level, f, args...) } diff --git a/nsqlookupd/nsqlookupd.go b/nsqlookupd/nsqlookupd.go index 7b10a3440..e280b11e2 100644 --- a/nsqlookupd/nsqlookupd.go +++ b/nsqlookupd/nsqlookupd.go @@ -7,6 +7,7 @@ import ( "sync" "github.com/nsqio/nsq/internal/http_api" + "github.com/nsqio/nsq/internal/lg" "github.com/nsqio/nsq/internal/protocol" "github.com/nsqio/nsq/internal/util" "github.com/nsqio/nsq/internal/version" @@ -30,10 +31,10 @@ func New(opts *Options) *NSQLookupd { DB: NewRegistrationDB(), } - // check log-level is valid and translate to int - n.opts.logLevel = n.logLevelFromString(opts.LogLevel) - if n.opts.logLevel == -1 { - n.logf(LOG_FATAL, "log level '%s' should be one of: debug, info, warn, error, or fatal", opts.LogLevel) + var err error + opts.logLevel, err = lg.ParseLogLevel(opts.LogLevel, opts.Verbose) + if err != nil { + n.logf(LOG_FATAL, "%s", err) os.Exit(1) } diff --git a/nsqlookupd/nsqlookupd_test.go b/nsqlookupd/nsqlookupd_test.go index 5852ce5b0..19f2f2b2c 100644 --- a/nsqlookupd/nsqlookupd_test.go +++ b/nsqlookupd/nsqlookupd_test.go @@ -67,16 +67,6 @@ func identify(t *testing.T, conn net.Conn) { test.Nil(t, err) } -func TestNoLogger(t *testing.T) { - opts := NewOptions() - opts.Logger = nil - opts.TCPAddress = "127.0.0.1:0" - opts.HTTPAddress = "127.0.0.1:0" - nsqlookupd := New(opts) - - nsqlookupd.logf(LOG_FATAL, "should never be logged") -} - func TestBasicLookupd(t *testing.T) { opts := NewOptions() opts.Logger = test.NewTestLogger(t) @@ -378,63 +368,3 @@ func TestCrashingLogger(t *testing.T) { } t.Fatalf("process ran with err %v, want exit status 1", err) } - -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 - opts.TCPAddress = "127.0.0.1:0" - opts.HTTPAddress = "127.0.0.1:0" - - // Test only fatal get through - opts.LogLevel = "FaTaL" - nsqlookupd := New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqlookupd.logf(i, "Test") - } - test.Equal(t, 1, logger.Count) - nsqlookupd.Exit() - - // Test only warnings or higher get through - opts.LogLevel = "WARN" - nsqlookupd = New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqlookupd.logf(i, "Test") - } - test.Equal(t, 3, logger.Count) - nsqlookupd.Exit() - - // Test everything gets through - opts.LogLevel = "debuG" - nsqlookupd = New(opts) - logger.Count = 0 - for i := 1; i <= 5; i++ { - nsqlookupd.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) - nsqlookupd.Exit() - - // Test everything gets through with verbose = true - logger.Count = 0 - opts.LogLevel = "fatal" - nsqlookupd = New(opts) - opts.Verbose = true - for i := 1; i <= 5; i++ { - nsqlookupd.logf(i, "Test") - } - test.Equal(t, 5, logger.Count) - nsqlookupd.Exit() - -} diff --git a/nsqlookupd/options.go b/nsqlookupd/options.go index 2217111a0..6258272ac 100644 --- a/nsqlookupd/options.go +++ b/nsqlookupd/options.go @@ -4,6 +4,8 @@ import ( "log" "os" "time" + + "github.com/nsqio/nsq/internal/lg" ) type Options struct { @@ -11,7 +13,7 @@ type Options struct { LogPrefix string `flag:"log-prefix"` Verbose bool `flag:"verbose"` // for backwards compatibility Logger Logger - logLevel int // private, not really an option + logLevel lg.LogLevel // private, not really an option TCPAddress string `flag:"tcp-address"` HTTPAddress string `flag:"http-address"` From c2c139db57fc12be035a8963d7adfbaea86804f9 Mon Sep 17 00:00:00 2001 From: Pierce Lopez Date: Mon, 22 May 2017 00:32:38 -0400 Subject: [PATCH 5/5] use app.logf() for internal packages for nsqd nsqlookupd nsqadmin Instead of setting a Logger for github.com/nsqio/nsq/internal packages, pass a logf() function, so it is called with and honors a LogLevel. * internal/clusterinfo/ * internal/http_api/ * internal/protocol/ nsqd lookupPeer also needed to be converted Get rid of interal.app.Logger type, but internal/test/ needs its own Logger definition to avoid circular import with internal/lg/ tests. --- internal/app/logger.go | 5 ----- internal/clusterinfo/data.go | 14 +++++--------- internal/http_api/api_response.go | 22 +++++++++++----------- internal/http_api/http_server.go | 17 ++++++++--------- internal/lg/lg.go | 2 ++ internal/protocol/tcp_server.go | 13 ++++++------- internal/test/logger.go | 8 ++++---- nsqadmin/http.go | 10 +++++----- nsqadmin/nsqadmin.go | 2 +- nsqd/http.go | 8 ++++---- nsqd/lookup.go | 2 +- nsqd/lookup_peer.go | 9 +++++---- nsqd/nsqd.go | 10 ++++++---- nsqlookupd/http.go | 8 ++++---- nsqlookupd/nsqlookupd.go | 4 ++-- 15 files changed, 64 insertions(+), 70 deletions(-) delete mode 100644 internal/app/logger.go diff --git a/internal/app/logger.go b/internal/app/logger.go deleted file mode 100644 index e5f7d134e..000000000 --- a/internal/app/logger.go +++ /dev/null @@ -1,5 +0,0 @@ -package app - -type Logger interface { - Output(maxdepth int, s string) error -} diff --git a/internal/clusterinfo/data.go b/internal/clusterinfo/data.go index 235b2484a..0eb85f070 100644 --- a/internal/clusterinfo/data.go +++ b/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,16 +34,12 @@ 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, @@ -50,10 +47,9 @@ func New(log logger, client *http_api.Client) *ClusterInfo { } 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 diff --git a/internal/http_api/api_response.go b/internal/http_api/api_response.go index 9debc6f04..0d56cd3ba 100644 --- a/internal/http_api/api_response.go +++ b/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) }) } diff --git a/internal/http_api/http_server.go b/internal/http_api/http_server.go index 3f787bd42..e02b51cfc 100644 --- a/internal/http_api/http_server.go +++ b/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()) } diff --git a/internal/lg/lg.go b/internal/lg/lg.go index 9c8bc925e..74936b132 100644 --- a/internal/lg/lg.go +++ b/internal/lg/lg.go @@ -16,6 +16,8 @@ const ( FATAL = LogLevel(5) ) +type AppLogFunc func(lvl LogLevel, f string, args ...interface{}) + type Logger interface { Output(maxdepth int, s string) error } diff --git a/internal/protocol/tcp_server.go b/internal/protocol/tcp_server.go index f06dff544..20b39d295 100644 --- a/internal/protocol/tcp_server.go +++ b/internal/protocol/tcp_server.go @@ -1,37 +1,36 @@ package protocol import ( - "fmt" "net" "runtime" "strings" - "github.com/nsqio/nsq/internal/app" + "github.com/nsqio/nsq/internal/lg" ) type TCPHandler interface { Handle(net.Conn) } -func TCPServer(listener net.Listener, handler TCPHandler, l app.Logger) { - l.Output(2, fmt.Sprintf("TCP: listening on %s", listener.Addr())) +func TCPServer(listener net.Listener, handler TCPHandler, logf lg.AppLogFunc) { + logf(lg.INFO, "TCP: listening on %s", listener.Addr()) for { clientConn, err := listener.Accept() if err != nil { if nerr, ok := err.(net.Error); ok && nerr.Temporary() { - l.Output(2, fmt.Sprintf("NOTICE: temporary Accept() failure - %s", err)) + logf(lg.WARN, "temporary Accept() failure - %s", err) runtime.Gosched() continue } // theres no direct way to detect this error because it is not exposed if !strings.Contains(err.Error(), "use of closed network connection") { - l.Output(2, fmt.Sprintf("ERROR: listener.Accept() - %s", err)) + logf(lg.ERROR, "listener.Accept() - %s", err) } break } go handler.Handle(clientConn) } - l.Output(2, fmt.Sprintf("TCP: closing %s", listener.Addr())) + logf(lg.INFO, "TCP: closing %s", listener.Addr()) } diff --git a/internal/test/logger.go b/internal/test/logger.go index 8ca542c5d..c64a615eb 100644 --- a/internal/test/logger.go +++ b/internal/test/logger.go @@ -1,8 +1,8 @@ package test -import ( - "github.com/nsqio/nsq/internal/app" -) +type Logger interface { + Output(maxdepth int, s string) error +} type tbLog interface { Log(...interface{}) @@ -17,6 +17,6 @@ func (tl *testLogger) Output(maxdepth int, s string) error { return nil } -func NewTestLogger(tbl tbLog) app.Logger { +func NewTestLogger(tbl tbLog) Logger { return &testLogger{tbl} } diff --git a/nsqadmin/http.go b/nsqadmin/http.go index bcd4430e2..62bd14914 100644 --- a/nsqadmin/http.go +++ b/nsqadmin/http.go @@ -55,21 +55,21 @@ type httpServer struct { } func NewHTTPServer(ctx *Context) *httpServer { - log := http_api.Log(ctx.nsqadmin.getOpts().Logger) + log := http_api.Log(ctx.nsqadmin.logf) client := http_api.NewClient(ctx.nsqadmin.httpClientTLSConfig, ctx.nsqadmin.getOpts().HTTPClientConnectTimeout, ctx.nsqadmin.getOpts().HTTPClientRequestTimeout) router := httprouter.New() router.HandleMethodNotAllowed = true - router.PanicHandler = http_api.LogPanicHandler(ctx.nsqadmin.getOpts().Logger) - router.NotFound = http_api.LogNotFoundHandler(ctx.nsqadmin.getOpts().Logger) - router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqadmin.getOpts().Logger) + router.PanicHandler = http_api.LogPanicHandler(ctx.nsqadmin.logf) + router.NotFound = http_api.LogNotFoundHandler(ctx.nsqadmin.logf) + router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqadmin.logf) s := &httpServer{ ctx: ctx, router: router, client: client, - ci: clusterinfo.New(ctx.nsqadmin.getOpts().Logger, client), + ci: clusterinfo.New(ctx.nsqadmin.logf, client), } router.Handle("GET", "/ping", http_api.Decorate(s.pingHandler, log, http_api.PlainText)) diff --git a/nsqadmin/nsqadmin.go b/nsqadmin/nsqadmin.go index b1ccba800..f4ba9c678 100644 --- a/nsqadmin/nsqadmin.go +++ b/nsqadmin/nsqadmin.go @@ -179,7 +179,7 @@ func (n *NSQAdmin) Main() { n.Unlock() httpServer := NewHTTPServer(&Context{n}) n.waitGroup.Wrap(func() { - http_api.Serve(n.httpListener, http_api.CompressHandler(httpServer), "HTTP", n.getOpts().Logger) + http_api.Serve(n.httpListener, http_api.CompressHandler(httpServer), "HTTP", n.logf) }) n.waitGroup.Wrap(func() { n.handleAdminActions() }) } diff --git a/nsqd/http.go b/nsqd/http.go index ff1e2d1fe..ddbfc1da6 100644 --- a/nsqd/http.go +++ b/nsqd/http.go @@ -32,13 +32,13 @@ type httpServer struct { } func newHTTPServer(ctx *context, tlsEnabled bool, tlsRequired bool) *httpServer { - log := http_api.Log(ctx.nsqd.getOpts().Logger) + log := http_api.Log(ctx.nsqd.logf) router := httprouter.New() router.HandleMethodNotAllowed = true - router.PanicHandler = http_api.LogPanicHandler(ctx.nsqd.getOpts().Logger) - router.NotFound = http_api.LogNotFoundHandler(ctx.nsqd.getOpts().Logger) - router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqd.getOpts().Logger) + router.PanicHandler = http_api.LogPanicHandler(ctx.nsqd.logf) + router.NotFound = http_api.LogNotFoundHandler(ctx.nsqd.logf) + router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqd.logf) s := &httpServer{ ctx: ctx, tlsEnabled: tlsEnabled, diff --git a/nsqd/lookup.go b/nsqd/lookup.go index c27572536..7bdbcca57 100644 --- a/nsqd/lookup.go +++ b/nsqd/lookup.go @@ -70,7 +70,7 @@ func (n *NSQD) lookupLoop() { continue } n.logf(LOG_INFO, "LOOKUP(%s): adding peer", host) - lookupPeer := newLookupPeer(host, n.getOpts().MaxBodySize, n.getOpts().Logger, + lookupPeer := newLookupPeer(host, n.getOpts().MaxBodySize, n.logf, connectCallback(n, hostname, syncTopicChan)) lookupPeer.Command(nil) // start the connection lookupPeers = append(lookupPeers, lookupPeer) diff --git a/nsqd/lookup_peer.go b/nsqd/lookup_peer.go index 848955e16..d4aa26f07 100644 --- a/nsqd/lookup_peer.go +++ b/nsqd/lookup_peer.go @@ -8,6 +8,7 @@ import ( "time" "github.com/nsqio/go-nsq" + "github.com/nsqio/nsq/internal/lg" ) // lookupPeer is a low-level type for connecting/reading/writing to nsqlookupd @@ -16,7 +17,7 @@ import ( // gracefully (i.e. it is all handled by the library). Clients can simply use the // Command interface to perform a round-trip. type lookupPeer struct { - l Logger + logf lg.AppLogFunc addr string conn net.Conn state int32 @@ -36,9 +37,9 @@ type peerInfo struct { // newLookupPeer creates a new lookupPeer instance connecting to the supplied address. // // The supplied connectCallback will be called *every* time the instance connects. -func newLookupPeer(addr string, maxBodySize int64, l Logger, connectCallback func(*lookupPeer)) *lookupPeer { +func newLookupPeer(addr string, maxBodySize int64, l lg.AppLogFunc, connectCallback func(*lookupPeer)) *lookupPeer { return &lookupPeer{ - l: l, + logf: l, addr: addr, state: stateDisconnected, maxBodySize: maxBodySize, @@ -48,7 +49,7 @@ func newLookupPeer(addr string, maxBodySize int64, l Logger, connectCallback fun // Connect will Dial the specified address, with timeouts func (lp *lookupPeer) Connect() error { - lp.l.Output(2, fmt.Sprintf("LOOKUP connecting to %s", lp.addr)) + lp.logf(lg.INFO, "LOOKUP connecting to %s", lp.addr) conn, err := net.DialTimeout("tcp", lp.addr, time.Second) if err != nil { return err diff --git a/nsqd/nsqd.go b/nsqd/nsqd.go index cb363be39..1649d5d25 100644 --- a/nsqd/nsqd.go +++ b/nsqd/nsqd.go @@ -87,9 +87,11 @@ func New(opts *Options) *NSQD { exitChan: make(chan int), notifyChan: make(chan interface{}), optsNotificationChan: make(chan struct{}, 1), - ci: clusterinfo.New(opts.Logger, http_api.NewClient(nil, opts.HTTPClientConnectTimeout, opts.HTTPClientRequestTimeout)), dl: dirlock.New(dataPath), } + httpcli := http_api.NewClient(nil, opts.HTTPClientConnectTimeout, opts.HTTPClientRequestTimeout) + n.ci = clusterinfo.New(n.logf, httpcli) + n.swapOpts(opts) n.errValue.Store(errStore{}) @@ -226,7 +228,7 @@ func (n *NSQD) Main() { n.Unlock() tcpServer := &tcpServer{ctx: ctx} n.waitGroup.Wrap(func() { - protocol.TCPServer(n.tcpListener, tcpServer, n.getOpts().Logger) + protocol.TCPServer(n.tcpListener, tcpServer, n.logf) }) if n.tlsConfig != nil && n.getOpts().HTTPSAddress != "" { @@ -240,7 +242,7 @@ func (n *NSQD) Main() { n.Unlock() httpsServer := newHTTPServer(ctx, true, true) n.waitGroup.Wrap(func() { - http_api.Serve(n.httpsListener, httpsServer, "HTTPS", n.getOpts().Logger) + http_api.Serve(n.httpsListener, httpsServer, "HTTPS", n.logf) }) } httpListener, err = net.Listen("tcp", n.getOpts().HTTPAddress) @@ -253,7 +255,7 @@ func (n *NSQD) Main() { n.Unlock() httpServer := newHTTPServer(ctx, false, n.getOpts().TLSRequired == TLSRequired) n.waitGroup.Wrap(func() { - http_api.Serve(n.httpListener, httpServer, "HTTP", n.getOpts().Logger) + http_api.Serve(n.httpListener, httpServer, "HTTP", n.logf) }) n.waitGroup.Wrap(func() { n.queueScanLoop() }) diff --git a/nsqlookupd/http.go b/nsqlookupd/http.go index a00dbd540..22bea8831 100644 --- a/nsqlookupd/http.go +++ b/nsqlookupd/http.go @@ -18,13 +18,13 @@ type httpServer struct { } func newHTTPServer(ctx *Context) *httpServer { - log := http_api.Log(ctx.nsqlookupd.opts.Logger) + log := http_api.Log(ctx.nsqlookupd.logf) router := httprouter.New() router.HandleMethodNotAllowed = true - router.PanicHandler = http_api.LogPanicHandler(ctx.nsqlookupd.opts.Logger) - router.NotFound = http_api.LogNotFoundHandler(ctx.nsqlookupd.opts.Logger) - router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqlookupd.opts.Logger) + router.PanicHandler = http_api.LogPanicHandler(ctx.nsqlookupd.logf) + router.NotFound = http_api.LogNotFoundHandler(ctx.nsqlookupd.logf) + router.MethodNotAllowed = http_api.LogMethodNotAllowedHandler(ctx.nsqlookupd.logf) s := &httpServer{ ctx: ctx, router: router, diff --git a/nsqlookupd/nsqlookupd.go b/nsqlookupd/nsqlookupd.go index e280b11e2..ca41faf40 100644 --- a/nsqlookupd/nsqlookupd.go +++ b/nsqlookupd/nsqlookupd.go @@ -55,7 +55,7 @@ func (l *NSQLookupd) Main() { l.Unlock() tcpServer := &tcpServer{ctx: ctx} l.waitGroup.Wrap(func() { - protocol.TCPServer(tcpListener, tcpServer, l.opts.Logger) + protocol.TCPServer(tcpListener, tcpServer, l.logf) }) httpListener, err := net.Listen("tcp", l.opts.HTTPAddress) @@ -68,7 +68,7 @@ func (l *NSQLookupd) Main() { l.Unlock() httpServer := newHTTPServer(ctx) l.waitGroup.Wrap(func() { - http_api.Serve(httpListener, httpServer, "HTTP", l.opts.Logger) + http_api.Serve(httpListener, httpServer, "HTTP", l.logf) }) }