opt: refine the logging module

eventloop_unix.go

@@ -64,8 +64,13 @@ func (el *eventloop) loopRun() {
 	if el.idx == 0 && el.svr.opts.Ticker {
 		go el.loopTicker()
 	}
+	switch err := el.poller.Polling(el.handleEvent); err {
+	case errServerShutdown:
+		el.svr.logger.Infof("Event-loop(%d) is exiting normally on the signal error: %v", el.idx, err)
+	default:
+		el.svr.logger.Fatalf("Event-loop(%d) is exiting due to an unexpected error: %v", el.idx, err)
 
-	el.svr.logger.Printf("event-loop:%d exits with error: %v\n", el.idx, el.poller.Polling(el.handleEvent))
+	}
 }
 
 func (el *eventloop) loopAccept(fd int) error {
@@ -193,10 +198,11 @@ func (el *eventloop) loopCloseConn(c *conn, err error) error {
 		c.releaseTCP()
 	} else {
 		if err0 != nil {
-			el.svr.logger.Printf("failed to delete fd:%d from poller, error:%v\n", c.fd, err0)
+			el.svr.logger.Warnf("Failed to delete fd=%d from poller in event-loop(%d), %v", c.fd, el.idx, err0)
 		}
 		if err1 != nil {
-			el.svr.logger.Printf("failed to close fd:%d, error:%v\n", c.fd, os.NewSyscallError("close", err1))
+			el.svr.logger.Warnf("Failed to close fd=%d in event-loop(%d), %v",
+				c.fd, el.idx, os.NewSyscallError("close", err1))
 		}
 	}
 	return nil
@@ -232,7 +238,7 @@ func (el *eventloop) loopTicker() {
 			return
 		})
 		if err != nil {
-			el.svr.logger.Printf("failed to awake poller with error:%v, stopping ticker\n", err)
+			el.svr.logger.Errorf("Failed to awake poller in event-loop(%d), error:%v, stopping ticker", el.idx, err)
 			break
 		}
 		if delay, open = <-el.svr.ticktock; open {
@@ -260,7 +266,8 @@ func (el *eventloop) loopReadUDP(fd int) error {
 	n, sa, err := unix.Recvfrom(fd, el.packet, 0)
 	if err != nil || n == 0 {
 		if err != nil && err != unix.EAGAIN {
-			el.svr.logger.Printf("failed to read UDP packet from fd:%d, error:%v\n", fd, os.NewSyscallError("recvfrom", err))
+			el.svr.logger.Warnf("Failed to read UDP packet from fd=%d in event-loop(%d), %v",
+				fd, el.idx, os.NewSyscallError("recvfrom", err))
 		}
 		return nil
 	}

eventloop_windows.go

@@ -71,7 +71,7 @@ func (el *eventloop) loopRun() {
 			err = v()
 		}
 		if err != nil {
-			el.svr.logger.Printf("event-loop:%d exits with error:%v\n", el.idx, err)
+			el.svr.logger.Fatalf("Event-loop(%d) is exiting due to an unexpected error: %v", el.idx, err)
 			break
 		}
 	}
@@ -182,7 +182,7 @@ func (el *eventloop) loopError(c *stdConn, err error) (e error) {
 		}
 		c.releaseTCP()
 	} else {
-		el.svr.logger.Printf("failed to close connection:%s, error:%v\n", c.remoteAddr.String(), e)
+		el.svr.logger.Warnf("Failed to close connection(%s), error: %v", c.remoteAddr.String(), e)
 	}
 	return
 }

gnet.go

@@ -26,6 +26,8 @@ import (
 	"strings"
 	"sync/atomic"
 	"time"
+
+	"github.com/panjf2000/gnet/logging"
 )
 
 // Action is an action that occurs after the completion of an event.
@@ -231,8 +233,9 @@ func Serve(eventHandler EventHandler, protoAddr string, opts ...Option) (err err
 	options := loadOptions(opts...)
 
 	if options.Logger != nil {
-		defaultLogger = options.Logger
+		logging.DefaultLogger = options.Logger
 	}
+	defer logging.Cleanup()
 
 	network, addr := parseProtoAddr(protoAddr)
 
@@ -258,6 +261,6 @@ func parseProtoAddr(addr string) (network, address string) {
 
 func sniffErrorAndLog(err error) {
 	if err != nil {
-		defaultLogger.Printf(err.Error())
+		logging.DefaultLogger.Errorf(err.Error())
 	}
 }

gnet_test.go

@@ -26,10 +26,8 @@ import (
 	"encoding/binary"
 	"fmt"
 	"io"
-	"log"
 	"math/rand"
 	"net"
-	"os"
 	"runtime"
 	"sync/atomic"
 	"testing"
@@ -38,6 +36,7 @@ import (
 	"github.com/panjf2000/gnet/pool/bytebuffer"
 	"github.com/panjf2000/gnet/pool/goroutine"
 	"github.com/valyala/bytebufferpool"
+	"go.uber.org/zap"
 )
 
 func TestCodecServe(t *testing.T) {
@@ -661,8 +660,10 @@ func (t *testWakeConnServer) Tick() (delay time.Duration, action Action) {
 
 func testWakeConn(network, addr string) {
 	svr := &testWakeConnServer{network: network, addr: addr}
+	logger := zap.NewExample()
+	defer logger.Sync()
 	must(Serve(svr, network+"://"+addr, WithTicker(true), WithNumEventLoop(2*runtime.NumCPU()),
-		WithLogger(log.New(os.Stderr, "", log.LstdFlags))))
+		WithLogger(logger.Sugar())))
 }
 
 func TestShutdown(t *testing.T) {

go.mod

@@ -6,5 +6,6 @@ require (
 	github.com/panjf2000/ants/v2 v2.4.1
 	github.com/smallnest/goframe v1.0.0
 	github.com/valyala/bytebufferpool v1.0.0
+	go.uber.org/zap v1.15.0
 	golang.org/x/sys v0.0.0-20200625212154-ddb9806d33ae
 )

go.sum

@@ -1,22 +1,66 @@
+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 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
 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=
+github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI=
+github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
+github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
+github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
+github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
+github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
+github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/panjf2000/ants/v2 v2.4.1 h1:7RtUqj5lGOw0WnZhSKDZ2zzJhaX5490ZW1sUolRXCxY=
 github.com/panjf2000/ants/v2 v2.4.1/go.mod h1:f6F0NZVFsGCp5A7QW/Zj/m92atWwOkY0OIhFxRNFr4A=
+github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I=
+github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
 github.com/smallnest/goframe v1.0.0 h1:ywsSz9P5BFiqn39w8iFDENTdqN44v+B5bp1PbCH+PVw=
 github.com/smallnest/goframe v1.0.0/go.mod h1:Dy8560GXrB6w5OJnVBU71dJtSyINdnqHHe6atDaZX00=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw=
 github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyCJ6HpOuEn7z0Csc=
+go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk=
+go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
+go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A=
+go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
+go.uber.org/zap v1.15.0 h1:ZZCA22JRF2gQE5FoNmhmrf7jeJJ2uhqDUNRYKm8dvmM=
+go.uber.org/zap v1.15.0/go.mod h1:Mb2vm2krFEG5DV0W9qcHBYFtp/Wku1cvYaqPsS/WYfc=
+golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
+golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
+golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs=
+golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
+golang.org/x/mod v0.0.0-20190513183733-4bf6d317e70e/go.mod h1:mXi4GBBbnImb6dmsKGUJ2LatrhH/nqhxcFungHvyanc=
+golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
+golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200625212154-ddb9806d33ae h1:Ih9Yo4hSPImZOpfGuA4bR/ORKTAbhZo2AbWNRCnevdo=
 golang.org/x/sys v0.0.0-20200625212154-ddb9806d33ae/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
+golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
+golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
+golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5 h1:hKsoRgsbwY1NafxrwTs+k64bikrLBkAgPir1TNCj3Zs=
+golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 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/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.7 h1:VUgggvou5XRW9mHwD/yXxIYSMtY0zoKQf/v226p2nyo=
 gopkg.in/yaml.v2 v2.2.7/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+honnef.co/go/tools v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM=
+honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg=

internal/netpoll/epoll.go

@@ -24,11 +24,11 @@
 package netpoll
 
 import (
-	"log"
 	"os"
 	"unsafe"
 
 	"github.com/panjf2000/gnet/internal"
+	"github.com/panjf2000/gnet/logging"
 	"golang.org/x/sys/unix"
 )
 
@@ -94,7 +94,7 @@ func (p *Poller) Polling(callback func(fd int, ev uint32) error) (err error) {
 	for {
 		n, err0 := unix.EpollWait(p.fd, el.events, -1)
 		if err0 != nil && err0 != unix.EINTR {
-			log.Println(os.NewSyscallError("epoll_wait", err0))
+			logging.DefaultLogger.Warnf("Error occurs in epoll, %v", os.NewSyscallError("epoll_wait", err0))
 			continue
 		}
 		for i := 0; i < n; i++ {

internal/netpoll/kqueue.go

@@ -24,10 +24,10 @@
 package netpoll
 
 import (
-	"log"
 	"os"
 
 	"github.com/panjf2000/gnet/internal"
+	"github.com/panjf2000/gnet/logging"
 	"golang.org/x/sys/unix"
 )
 
@@ -85,7 +85,7 @@ func (p *Poller) Polling(callback func(fd int, filter int16) error) (err error)
 	for {
 		n, err0 := unix.Kevent(p.fd, nil, el.events, nil)
 		if err0 != nil && err0 != unix.EINTR {
-			log.Println(os.NewSyscallError("kevent wait", err0))
+			logging.DefaultLogger.Warnf("Error occurs in kqueue, %v", os.NewSyscallError("kevent wait", err0))
 			continue
 		}
 		var evFilter int16

logging/logger.go

@@ -0,0 +1,53 @@
+// Copyright (c) 2020 Andy Pan
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in all
+// copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+// SOFTWARE.
+
+package logging
+
+import "go.uber.org/zap"
+
+var (
+	// DefaultLogger is the default logger inside the gnet server.
+	DefaultLogger Logger
+	zapLogger     *zap.Logger
+)
+
+func init() {
+	zapLogger, _ = zap.NewDevelopment()
+	DefaultLogger = zapLogger.Sugar()
+}
+
+// Cleanup do something windup for logger, like closing, flushing, etc.
+func Cleanup() {
+	_ = zapLogger.Sync()
+}
+
+// Logger is used for logging formatted messages.
+type Logger interface {
+	// Debugf logs messages at DEBUG level.
+	Debugf(format string, args ...interface{})
+	// Infof logs messages at INFO level.
+	Infof(format string, args ...interface{})
+	// Warnf logs messages at WARN level.
+	Warnf(format string, args ...interface{})
+	// Errorf logs messages at ERROR level.
+	Errorf(format string, args ...interface{})
+	// Fatalf logs messages at FATAL level.
+	Fatalf(format string, args ...interface{})
+}

options.go

@@ -20,7 +20,11 @@
 
 package gnet
 
-import "time"
+import (
+	"time"
+
+	"github.com/panjf2000/gnet/logging"
+)
 
 // Option is a function that will set up option.
 type Option func(opts *Options)
@@ -61,8 +65,8 @@ type Options struct {
 	Codec ICodec
 
 	// Logger is the customized logger for logging info, if it is not set,
-	// default standard logger from log package is used.
-	Logger Logger
+	// then gnet will use the default logger powered by go.uber.org/zap.
+	Logger logging.Logger
 }
 
 // WithOptions sets up all options.
@@ -122,7 +126,7 @@ func WithCodec(codec ICodec) Option {
 }
 
 // WithLogger sets up a customized logger.
-func WithLogger(logger Logger) Option {
+func WithLogger(logger logging.Logger) Option {
 	return func(opts *Options) {
 		opts.Logger = logger
 	}

reactor_bsd.go

@@ -26,10 +26,13 @@ import "github.com/panjf2000/gnet/internal/netpoll"
 
 func (svr *server) activateMainReactor() {
 	defer svr.signalShutdown()
+	switch err := svr.mainLoop.poller.Polling(func(fd int, filter int16) error { return svr.acceptNewConnection(fd) }); err {
+	case errServerShutdown:
+		svr.logger.Infof("Main reactor is exiting normally on the signal error: %v", err)
+	default:
+		svr.logger.Fatalf("Main reactor is exiting due to an unexpected error: %v", err)
 
-	svr.logger.Printf("main reactor exits with error:%v\n", svr.mainLoop.poller.Polling(func(fd int, filter int16) error {
-		return svr.acceptNewConnection(fd)
-	}))
+	}
 }
 
 func (svr *server) activateSubReactor(el *eventloop) {
@@ -44,8 +47,7 @@ func (svr *server) activateSubReactor(el *eventloop) {
 	if el.idx == 0 && svr.opts.Ticker {
 		go el.loopTicker()
 	}
-
-	svr.logger.Printf("event-loop:%d exits with error:%v\n", el.idx, el.poller.Polling(func(fd int, filter int16) error {
+	switch err := el.poller.Polling(func(fd int, filter int16) error {
 		if c, ack := el.connections[fd]; ack {
 			if filter == netpoll.EVFilterSock {
 				return el.loopCloseConn(c, nil)
@@ -67,5 +69,10 @@ func (svr *server) activateSubReactor(el *eventloop) {
 			}
 		}
 		return nil
-	}))
+	}); err {
+	case errServerShutdown:
+		svr.logger.Infof("Event-loop(%d) is exiting normally on the signal error: %v", el.idx, err)
+	default:
+		svr.logger.Fatalf("Event-loop(%d) is exiting due to an unexpected error: %v", el.idx, err)
+	}
 }