opt: improve the logging logic

eventloop_unix.go

@@ -34,6 +34,7 @@ import (
 	"unsafe"
 
 	gerrors "github.com/panjf2000/gnet/errors"
+	"github.com/panjf2000/gnet/internal/logging"
 	"github.com/panjf2000/gnet/internal/netpoll"
 	"github.com/panjf2000/gnet/internal/socket"
 	"golang.org/x/sys/unix"
@@ -87,7 +88,7 @@ func (el *eventloop) loopRun(lockOSThread bool) {
 	}()
 
 	err := el.poller.Polling(el.handleEvent)
-	el.svr.logger.Infof("Event-loop(%d) is exiting due to error: %v", el.idx, err)
+	logging.Infof("Event-loop(%d) is exiting due to error: %v", el.idx, err)
 }
 
 func (el *eventloop) loopAccept(fd int) error {
@@ -285,7 +286,7 @@ func (el *eventloop) loopTicker(ctx context.Context) {
 		case None:
 		case Shutdown:
 			err := el.poller.Trigger(func() error { return gerrors.ErrServerShutdown })
-			el.svr.logger.Debugf("stopping ticker in event-loop(%d) from Tick(), Trigger:%v", el.idx, err)
+			logging.Debugf("stopping ticker in event-loop(%d) from Tick(), Trigger:%v", el.idx, err)
 		}
 		if timer == nil {
 			timer = time.NewTimer(delay)
@@ -294,7 +295,7 @@ func (el *eventloop) loopTicker(ctx context.Context) {
 		}
 		select {
 		case <-ctx.Done():
-			el.svr.logger.Debugf("stopping ticker in event-loop(%d) from Server, error:%v", el.idx, ctx.Err())
+			logging.Debugf("stopping ticker in event-loop(%d) from Server, error:%v", el.idx, ctx.Err())
 			return
 		case <-timer.C:
 		}

eventloop_windows.go

@@ -28,6 +28,7 @@ import (
 	"time"
 	"unsafe"
 
+	"github.com/panjf2000/gnet/internal/logging"
 	"github.com/panjf2000/gnet/pool/bytebuffer"
 
 	"github.com/panjf2000/gnet/errors"
@@ -95,7 +96,7 @@ func (el *eventloop) loopRun(lockOSThread bool) {
 		if err == errors.ErrServerShutdown {
 			break
 		} else if err != nil {
-			el.svr.logger.Infof("Event-loop(%d) is exiting due to the error: %v", el.idx, err)
+			logging.Infof("Event-loop(%d) is exiting due to the error: %v", el.idx, err)
 		}
 	}
 }
@@ -183,7 +184,7 @@ func (el *eventloop) loopTicker(ctx context.Context) {
 		delay, action = el.eventHandler.Tick()
 		if action == Shutdown {
 			el.ch <- func() error { return errors.ErrServerShutdown }
-			el.svr.logger.Debugf("stopping ticker in event-loop(%d) from Tick()", el.idx)
+			logging.Debugf("stopping ticker in event-loop(%d) from Tick()", el.idx)
 		}
 		if timer == nil {
 			timer = time.NewTimer(delay)
@@ -192,7 +193,7 @@ func (el *eventloop) loopTicker(ctx context.Context) {
 		}
 		select {
 		case <-ctx.Done():
-			el.svr.logger.Debugf("stopping ticker in event-loop(%d) from Server, error:%v", el.idx, ctx.Err())
+			logging.Debugf("stopping ticker in event-loop(%d) from Server, error:%v", el.idx, ctx.Err())
 			return
 		case <-timer.C:
 		}
@@ -206,7 +207,7 @@ func (el *eventloop) loopError(c *stdConn, err error) (e error) {
 		}
 
 		if err = c.conn.Close(); err != nil {
-			el.svr.logger.Warnf("Failed to close connection(%s), error: %v", c.remoteAddr.String(), err)
+			logging.Warnf("Failed to close connection(%s), error: %v", c.remoteAddr.String(), err)
 			if e == nil {
 				e = err
 			}

gnet.go

@@ -87,7 +87,7 @@ func (s Server) CountConnections() (count int) {
 func (s Server) DupFd() (dupFD int, err error) {
 	dupFD, sc, err := s.svr.ln.Dup()
 	if err != nil {
-		logging.DefaultLogger.Warnf("%s failed when duplicating new fd\n", sc)
+		logging.Warnf("%s failed when duplicating new fd\n", sc)
 	}
 	return
 }
@@ -248,15 +248,23 @@ func (es *EventServer) Tick() (delay time.Duration, action Action) {
 func Serve(eventHandler EventHandler, protoAddr string, opts ...Option) (err error) {
 	options := loadOptions(opts...)
 
+	logging.Init(options.LogLevel)
+
+	if options.LogPath != "" {
+		err = logging.SetupLoggerWithPath(options.LogPath, options.LogLevel)
+	}
+	if err != nil {
+		return
+	}
 	if options.Logger != nil {
-		logging.DefaultLogger = options.Logger
+		logging.SetupLogger(options.Logger)
 	}
 	defer logging.Cleanup()
 
 	// The maximum number of operating system threads that the Go program can use is initially set to 10000,
 	// which should be the maximum amount of I/O event-loops locked to OS threads users can start up.
 	if options.LockOSThread && options.NumEventLoop > 10000 {
-		logging.DefaultLogger.Errorf("too many event-loops under LockOSThread mode, should be less than 10,000 "+
+		logging.Errorf("too many event-loops under LockOSThread mode, should be less than 10,000 "+
 			"while you are trying to set up %d\n", options.NumEventLoop)
 		return errors.ErrTooManyEventLoopThreads
 	}
@@ -325,9 +333,3 @@ func parseProtoAddr(addr string) (network, address string) {
 	}
 	return
 }
-
-func sniffErrorAndLog(err error) {
-	if err != nil {
-		logging.DefaultLogger.Errorf(err.Error())
-	}
-}

gnet_test.go

@@ -39,6 +39,7 @@ import (
 	"github.com/panjf2000/gnet/pool/bytebuffer"
 	"github.com/panjf2000/gnet/pool/goroutine"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 )
 
 func TestCodecServe(t *testing.T) {
@@ -258,7 +259,7 @@ func testCodecServe(network, addr string, multicore, async bool, nclients int, r
 		network: network, addr: addr, multicore: multicore, async: async, nclients: nclients,
 		codec: codec, workerPool: goroutine.Default(),
 	}
-	err = Serve(ts, network+"://"+addr, WithMulticore(multicore), WithTicker(true),
+	err = Serve(ts, network+"://"+addr, WithMulticore(multicore), WithTicker(true), WithLogLevel(zapcore.DebugLevel),
 		WithTCPKeepAlive(time.Minute*5), WithSocketRecvBuffer(8*1024), WithSocketSendBuffer(8*1024), WithCodec(codec), WithReusePort(reuseport))
 	if err != nil {
 		panic(err)

go.mod

@@ -3,10 +3,12 @@ module github.com/panjf2000/gnet
 go 1.16
 
 require (
+	github.com/BurntSushi/toml v0.3.1 // indirect
 	github.com/panjf2000/ants/v2 v2.4.6
 	github.com/valyala/bytebufferpool v1.0.0
 	go.uber.org/atomic v1.8.0 // indirect
 	go.uber.org/multierr v1.7.0 // indirect
 	go.uber.org/zap v1.17.0
 	golang.org/x/sys v0.0.0-20210616094352-59db8d763f22
+	gopkg.in/natefinch/lumberjack.v2 v2.0.0
 )

go.sum

@@ -1,3 +1,5 @@
+github.com/BurntSushi/toml v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
+github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -26,6 +28,8 @@ golang.org/x/sys v0.0.0-20210616094352-59db8d763f22 h1:RqytpXGR1iVNX7psjB3ff8y7s
 golang.org/x/sys v0.0.0-20210616094352-59db8d763f22/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/natefinch/lumberjack.v2 v2.0.0 h1:1Lc07Kr7qY4U2YPouBjpCLxpiyxIVoxqXgkXLknAOE8=
+gopkg.in/natefinch/lumberjack.v2 v2.0.0/go.mod h1:l0ndWWf7gzL7RNwBG7wST/UCcT4T24xpD6X8LsfU/+k=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.7/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=

internal/logging/logger.go

@@ -37,32 +37,118 @@
 package logging
 
 import (
-	"os"
-	"strings"
+	"errors"
+	"sync"
 
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"gopkg.in/natefinch/lumberjack.v2"
 )
 
 var (
-	// DefaultLogger is the default logger inside the gnet server.
+	// DefaultLogger is the default logger inside the tbuspp client.
 	DefaultLogger Logger
 	zapLogger     *zap.Logger
+	loggingLevel  zapcore.Level
+
+	once sync.Once
 )
 
-func init() {
-	switch strings.ToLower(os.Getenv("GNET_LOGGING_MODE")) {
-	case "prod":
-		zapLogger, _ = zap.NewProduction()
-	default:
-		// Other values except "Prod" create the development logger for gnet server.
-		zapLogger, _ = zap.NewDevelopment()
+// Init initializes the inside default logger of client.
+func Init(logLevel zapcore.Level) {
+	once.Do(func() {
+		cfg := zap.NewDevelopmentConfig()
+		loggingLevel = logLevel
+		cfg.Level = zap.NewAtomicLevelAt(logLevel)
+		zapLogger, _ = cfg.Build()
+		DefaultLogger = zapLogger.Sugar()
+	})
+}
+
+func getEncoder() zapcore.Encoder {
+	encoderConfig := zap.NewProductionEncoderConfig()
+	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+	encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder
+	return zapcore.NewConsoleEncoder(encoderConfig)
+}
+
+// SetupLoggerWithPath setups the logger by local file path.
+func SetupLoggerWithPath(localPath string, logLevel zapcore.Level) (err error) {
+	if len(localPath) == 0 {
+		return errors.New("invalid local logger path")
+	}
+
+	// lumberjack.Logger is already safe for concurrent use, so we don't need to lock it.
+	w := &lumberjack.Logger{
+		Filename:   localPath,
+		MaxSize:    100, // megabytes
+		MaxBackups: 3,
+		MaxAge:     28, // days
 	}
+
+	loggingLevel = logLevel
+	encoder := getEncoder()
+	syncer := zapcore.AddSync(w)
+	highPriority := zap.LevelEnablerFunc(func(level zapcore.Level) bool {
+		return level >= logLevel
+	})
+	core := zapcore.NewCore(encoder, syncer, highPriority)
+	zapLogger := zap.New(core, zap.AddCaller())
 	DefaultLogger = zapLogger.Sugar()
+	return nil
+}
+
+// SetupLogger setups the logger by the Logger interface.
+func SetupLogger(logger Logger) {
+	if logger == nil {
+		return
+	}
+	zapLogger = nil
+	DefaultLogger = logger
 }
 
 // Cleanup does something windup for logger, like closing, flushing, etc.
 func Cleanup() {
-	_ = zapLogger.Sync()
+	if zapLogger != nil {
+		_ = zapLogger.Sync()
+	}
+}
+
+// LogErr prints err if it's not nil.
+func LogErr(err error) {
+	if err != nil {
+		DefaultLogger.Errorf("error occurs during runtime, %v", err)
+	}
+}
+
+// Level returns the logging level.
+func Level() zapcore.Level {
+	return loggingLevel
+}
+
+// Debugf logs messages at DEBUG level.
+func Debugf(format string, args ...interface{}) {
+	DefaultLogger.Debugf(format, args...)
+}
+
+// Infof logs messages at INFO level.
+func Infof(format string, args ...interface{}) {
+	DefaultLogger.Infof(format, args...)
+}
+
+// Warnf logs messages at WARN level.
+func Warnf(format string, args ...interface{}) {
+	DefaultLogger.Warnf(format, args...)
+}
+
+// Errorf logs messages at ERROR level.
+func Errorf(format string, args ...interface{}) {
+	DefaultLogger.Errorf(format, args...)
+}
+
+// Fatalf logs messages at FATAL level.
+func Fatalf(format string, args ...interface{}) {
+	DefaultLogger.Errorf(format, args...)
 }
 
 // Logger is used for logging formatted messages.

internal/netpoll/epoll.go

@@ -106,7 +106,7 @@ func (p *Poller) Polling(callback func(fd int, ev uint32) error) error {
 			runtime.Gosched()
 			continue
 		} else if err != nil {
-			logging.DefaultLogger.Warnf("Error occurs in epoll: %v", os.NewSyscallError("epoll_wait", err))
+			logging.Warnf("Error occurs in epoll: %v", os.NewSyscallError("epoll_wait", err))
 			return err
 		}
 		msec = 0
@@ -118,7 +118,7 @@ func (p *Poller) Polling(callback func(fd int, ev uint32) error) error {
 				case errors.ErrAcceptSocket, errors.ErrServerShutdown:
 					return err
 				default:
-					logging.DefaultLogger.Warnf("Error occurs in event-loop: %v", err)
+					logging.Warnf("Error occurs in event-loop: %v", err)
 				}
 			} else {
 				wakenUp = true
@@ -138,7 +138,7 @@ func (p *Poller) Polling(callback func(fd int, ev uint32) error) error {
 				case errors.ErrServerShutdown:
 					return err
 				default:
-					logging.DefaultLogger.Warnf("Error occurs in user-defined function, %v", err)
+					logging.Warnf("Error occurs in user-defined function, %v", err)
 				}
 			}
 			atomic.StoreInt32(&p.netpollWakeSig, 0)

internal/netpoll/kqueue.go

@@ -100,7 +100,7 @@ func (p *Poller) Polling(callback func(fd int, filter int16) error) error {
 			runtime.Gosched()
 			continue
 		} else if err != nil {
-			logging.DefaultLogger.Warnf("Error occurs in kqueue: %v", os.NewSyscallError("kevent wait", err))
+			logging.Warnf("Error occurs in kqueue: %v", os.NewSyscallError("kevent wait", err))
 			return err
 		}
 		tsp = &ts
@@ -117,7 +117,7 @@ func (p *Poller) Polling(callback func(fd int, filter int16) error) error {
 				case errors.ErrAcceptSocket, errors.ErrServerShutdown:
 					return err
 				default:
-					logging.DefaultLogger.Warnf("Error occurs in event-loop: %v", err)
+					logging.Warnf("Error occurs in event-loop: %v", err)
 				}
 			} else {
 				wakenUp = true
@@ -136,7 +136,7 @@ func (p *Poller) Polling(callback func(fd int, filter int16) error) error {
 				case errors.ErrServerShutdown:
 					return err
 				default:
-					logging.DefaultLogger.Warnf("Error occurs in user-defined function, %v", err)
+					logging.Warnf("Error occurs in user-defined function, %v", err)
 				}
 			}
 			atomic.StoreInt32(&p.netpollWakeSig, 0)

listener_unix.go

@@ -29,6 +29,7 @@ import (
 	"time"
 
 	"github.com/panjf2000/gnet/errors"
+	"github.com/panjf2000/gnet/internal/logging"
 	"github.com/panjf2000/gnet/internal/netpoll"
 	"github.com/panjf2000/gnet/internal/socket"
 	"golang.org/x/sys/unix"
@@ -67,10 +68,10 @@ func (ln *listener) close() {
 	ln.once.Do(
 		func() {
 			if ln.fd > 0 {
-				sniffErrorAndLog(os.NewSyscallError("close", unix.Close(ln.fd)))
+				logging.LogErr(os.NewSyscallError("close", unix.Close(ln.fd)))
 			}
 			if ln.network == "unix" {
-				sniffErrorAndLog(os.RemoveAll(ln.addr))
+				logging.LogErr(os.RemoveAll(ln.addr))
 			}
 		})
 }