Merge pull request #9272 from gyuho/logger

clientv3: use "pkg.Logger"

.words

@@ -10,6 +10,7 @@ RPC
 RPCs
 TODO
 WithRequireLeader
+args
 backoff
 blackhole
 blackholed

clientv3/client.go

@@ -166,7 +166,7 @@ func (c *Client) autoSync() {
 			err := c.Sync(ctx)
 			cancel()
 			if err != nil && err != c.ctx.Err() {
-				logger.Println("Auto sync endpoints failed:", err)
+				lg.Lvl(4).Infof("Auto sync endpoints failed: %v", err)
 			}
 		}
 	}

clientv3/health_balancer.go

@@ -158,26 +158,26 @@ func (b *healthBalancer) pinned() string {
 
 func (b *healthBalancer) hostPortError(hostPort string, err error) {
 	if b.endpoint(hostPort) == "" {
-		logger.Lvl(4).Infof("clientv3/balancer: %q is stale (skip marking as unhealthy on %q)", hostPort, err.Error())
+		lg.Lvl(4).Infof("clientv3/balancer: %q is stale (skip marking as unhealthy on %q)", hostPort, err.Error())
 		return
 	}
 
 	b.unhealthyMu.Lock()
 	b.unhealthyHostPorts[hostPort] = time.Now()
 	b.unhealthyMu.Unlock()
-	logger.Lvl(4).Infof("clientv3/balancer: %q is marked unhealthy (%q)", hostPort, err.Error())
+	lg.Lvl(4).Infof("clientv3/balancer: %q is marked unhealthy (%q)", hostPort, err.Error())
 }
 
 func (b *healthBalancer) removeUnhealthy(hostPort, msg string) {
 	if b.endpoint(hostPort) == "" {
-		logger.Lvl(4).Infof("clientv3/balancer: %q was not in unhealthy (%q)", hostPort, msg)
+		lg.Lvl(4).Infof("clientv3/balancer: %q was not in unhealthy (%q)", hostPort, msg)
 		return
 	}
 
 	b.unhealthyMu.Lock()
 	delete(b.unhealthyHostPorts, hostPort)
 	b.unhealthyMu.Unlock()
-	logger.Lvl(4).Infof("clientv3/balancer: %q is removed from unhealthy (%q)", hostPort, msg)
+	lg.Lvl(4).Infof("clientv3/balancer: %q is removed from unhealthy (%q)", hostPort, msg)
 }
 
 func (b *healthBalancer) countUnhealthy() (count int) {
@@ -199,7 +199,7 @@ func (b *healthBalancer) cleanupUnhealthy() {
 	for k, v := range b.unhealthyHostPorts {
 		if time.Since(v) > b.healthCheckTimeout {
 			delete(b.unhealthyHostPorts, k)
-			logger.Lvl(4).Infof("clientv3/balancer: removed %q from unhealthy after %v", k, b.healthCheckTimeout)
+			lg.Lvl(4).Infof("clientv3/balancer: removed %q from unhealthy after %v", k, b.healthCheckTimeout)
 		}
 	}
 	b.unhealthyMu.Unlock()
@@ -402,7 +402,7 @@ func (b *healthBalancer) Up(addr grpc.Address) func(error) {
 	}
 
 	if b.pinAddr != "" {
-		logger.Lvl(4).Infof("clientv3/balancer: %q is up but not pinned (already pinned %q)", addr.Addr, b.pinAddr)
+		lg.Lvl(4).Infof("clientv3/balancer: %q is up but not pinned (already pinned %q)", addr.Addr, b.pinAddr)
 		return func(err error) {}
 	}
 
@@ -410,7 +410,7 @@ func (b *healthBalancer) Up(addr grpc.Address) func(error) {
 	close(b.upc)
 	b.downc = make(chan struct{})
 	b.pinAddr = addr.Addr
-	logger.Lvl(4).Infof("clientv3/balancer: pin %q", addr.Addr)
+	lg.Lvl(4).Infof("clientv3/balancer: pin %q", addr.Addr)
 
 	// notify client that a connection is up
 	b.readyOnce.Do(func() { close(b.readyc) })
@@ -427,7 +427,7 @@ func (b *healthBalancer) Up(addr grpc.Address) func(error) {
 		close(b.downc)
 		b.pinAddr = ""
 		b.mu.Unlock()
-		logger.Lvl(4).Infof("clientv3/balancer: unpin %q (%q)", addr.Addr, err.Error())
+		lg.Lvl(4).Infof("clientv3/balancer: unpin %q (%q)", addr.Addr, err.Error())
 	}
 }
 
@@ -454,7 +454,7 @@ func (b *healthBalancer) mayPin(addr grpc.Address) bool {
 	//   3. grpc-healthcheck still SERVING, thus retry to pin
 	// instead, return before grpc-healthcheck if failed within healthcheck timeout
 	if elapsed := time.Since(failedTime); elapsed < b.healthCheckTimeout {
-		logger.Lvl(4).Infof("clientv3/balancer: %q is up but not pinned (failed %v ago, require minimum %v after failure)", addr.Addr, elapsed, b.healthCheckTimeout)
+		lg.Lvl(4).Infof("clientv3/balancer: %q is up but not pinned (failed %v ago, require minimum %v after failure)", addr.Addr, elapsed, b.healthCheckTimeout)
 		return false
 	}
 

clientv3/logger.go

@@ -18,28 +18,14 @@ import (
 	"io/ioutil"
 	"sync"
 
+	"github.com/coreos/etcd/pkg/logger"
+
 	"google.golang.org/grpc/grpclog"
 )
 
-// Logger is the logger used by client library.
-// It implements grpclog.LoggerV2 interface.
-type Logger interface {
-	grpclog.LoggerV2
-
-	// Lvl returns logger if logger's verbosity level >= "lvl".
-	// Otherwise, logger that discards all logs.
-	Lvl(lvl int) Logger
-
-	// to satisfy capnslog
-
-	Print(args ...interface{})
-	Printf(format string, args ...interface{})
-	Println(args ...interface{})
-}
-
 var (
-	loggerMu sync.RWMutex
-	logger   Logger
+	lgMu sync.RWMutex
+	lg   logger.Logger
 )
 
 type settableLogger struct {
@@ -49,29 +35,29 @@ type settableLogger struct {
 
 func init() {
 	// disable client side logs by default
-	logger = &settableLogger{}
+	lg = &settableLogger{}
 	SetLogger(grpclog.NewLoggerV2(ioutil.Discard, ioutil.Discard, ioutil.Discard))
 }
 
 // SetLogger sets client-side Logger.
 func SetLogger(l grpclog.LoggerV2) {
-	loggerMu.Lock()
-	logger = NewLogger(l)
+	lgMu.Lock()
+	lg = logger.New(l)
 	// override grpclog so that any changes happen with locking
-	grpclog.SetLoggerV2(logger)
-	loggerMu.Unlock()
+	grpclog.SetLoggerV2(lg)
+	lgMu.Unlock()
 }
 
-// GetLogger returns the current logger.
-func GetLogger() Logger {
-	loggerMu.RLock()
-	l := logger
-	loggerMu.RUnlock()
+// GetLogger returns the current logger.Logger.
+func GetLogger() logger.Logger {
+	lgMu.RLock()
+	l := lg
+	lgMu.RUnlock()
 	return l
 }
 
-// NewLogger returns a new Logger with grpclog.LoggerV2.
-func NewLogger(gl grpclog.LoggerV2) Logger {
+// NewLogger returns a new Logger with logger.Logger.
+func NewLogger(gl grpclog.LoggerV2) logger.Logger {
 	return &settableLogger{l: gl}
 }
 
@@ -104,32 +90,12 @@ func (s *settableLogger) Print(args ...interface{})                 { s.get().In
 func (s *settableLogger) Printf(format string, args ...interface{}) { s.get().Infof(format, args...) }
 func (s *settableLogger) Println(args ...interface{})               { s.get().Infoln(args...) }
 func (s *settableLogger) V(l int) bool                              { return s.get().V(l) }
-func (s *settableLogger) Lvl(lvl int) Logger {
+func (s *settableLogger) Lvl(lvl int) grpclog.LoggerV2 {
 	s.mu.RLock()
 	l := s.l
 	s.mu.RUnlock()
 	if l.V(lvl) {
 		return s
 	}
-	return &noLogger{}
+	return logger.NewDiscardLogger()
 }
-
-type noLogger struct{}
-
-func (*noLogger) Info(args ...interface{})                    {}
-func (*noLogger) Infof(format string, args ...interface{})    {}
-func (*noLogger) Infoln(args ...interface{})                  {}
-func (*noLogger) Warning(args ...interface{})                 {}
-func (*noLogger) Warningf(format string, args ...interface{}) {}
-func (*noLogger) Warningln(args ...interface{})               {}
-func (*noLogger) Error(args ...interface{})                   {}
-func (*noLogger) Errorf(format string, args ...interface{})   {}
-func (*noLogger) Errorln(args ...interface{})                 {}
-func (*noLogger) Fatal(args ...interface{})                   {}
-func (*noLogger) Fatalf(format string, args ...interface{})   {}
-func (*noLogger) Fatalln(args ...interface{})                 {}
-func (*noLogger) Print(args ...interface{})                   {}
-func (*noLogger) Printf(format string, args ...interface{})   {}
-func (*noLogger) Println(args ...interface{})                 {}
-func (*noLogger) V(l int) bool                                { return false }
-func (ng *noLogger) Lvl(lvl int) Logger                       { return ng }

clientv3/retry.go

@@ -96,13 +96,13 @@ func (c *Client) newRetryWrapper() retryRPCFunc {
 			if err == nil {
 				return nil
 			}
-			logger.Lvl(4).Infof("clientv3/retry: error %q on pinned endpoint %q", err.Error(), pinned)
+			lg.Lvl(4).Infof("clientv3/retry: error %q on pinned endpoint %q", err.Error(), pinned)
 
 			if s, ok := status.FromError(err); ok && (s.Code() == codes.Unavailable || s.Code() == codes.DeadlineExceeded || s.Code() == codes.Internal) {
 				// mark this before endpoint switch is triggered
 				c.balancer.hostPortError(pinned, err)
 				c.balancer.next()
-				logger.Lvl(4).Infof("clientv3/retry: switching from %q due to error %q", pinned, err.Error())
+				lg.Lvl(4).Infof("clientv3/retry: switching from %q due to error %q", pinned, err.Error())
 			}
 
 			if isStop(err) {
@@ -120,12 +120,12 @@ func (c *Client) newAuthRetryWrapper(retryf retryRPCFunc) retryRPCFunc {
 			if err == nil {
 				return nil
 			}
-			logger.Lvl(4).Infof("clientv3/auth-retry: error %q on pinned endpoint %q", err.Error(), pinned)
+			lg.Lvl(4).Infof("clientv3/auth-retry: error %q on pinned endpoint %q", err.Error(), pinned)
 			// always stop retry on etcd errors other than invalid auth token
 			if rpctypes.Error(err) == rpctypes.ErrInvalidAuthToken {
 				gterr := c.getToken(rpcCtx)
 				if gterr != nil {
-					logger.Lvl(4).Infof("clientv3/auth-retry: cannot retry due to error %q(%q) on pinned endpoint %q", err.Error(), gterr.Error(), pinned)
+					lg.Lvl(4).Infof("clientv3/auth-retry: cannot retry due to error %q(%q) on pinned endpoint %q", err.Error(), gterr.Error(), pinned)
 					return err // return the original error for simplicity
 				}
 				continue

etcdctl/ctlv3/command/snapshot_command.go

@@ -24,7 +24,6 @@ import (
 	"github.com/coreos/etcd/pkg/types"
 	"github.com/coreos/etcd/snapshot"
 
-	"github.com/coreos/pkg/capnslog"
 	"github.com/spf13/cobra"
 )
 
@@ -103,7 +102,7 @@ func snapshotSaveCommandFunc(cmd *cobra.Command, args []string) {
 		ExitWithError(ExitError, err)
 	}
 	if debug {
-		lg = logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
+		lg = logger.NewPackageLogger("github.com/coreos/etcd", "snapshot")
 	}
 	sp := snapshot.NewV3(mustClientFromCmd(cmd), lg)
 
@@ -127,7 +126,7 @@ func snapshotStatusCommandFunc(cmd *cobra.Command, args []string) {
 		ExitWithError(ExitError, err)
 	}
 	if debug {
-		lg = logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
+		lg = logger.NewPackageLogger("github.com/coreos/etcd", "snapshot")
 	}
 	sp := snapshot.NewV3(nil, lg)
 
@@ -165,7 +164,7 @@ func snapshotRestoreCommandFunc(cmd *cobra.Command, args []string) {
 		ExitWithError(ExitError, err)
 	}
 	if debug {
-		lg = logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
+		lg = logger.NewPackageLogger("github.com/coreos/etcd", "snapshot")
 	}
 	sp := snapshot.NewV3(nil, lg)
 

pkg/logger/discard.go

@@ -14,9 +14,13 @@
 
 package logger
 
-import "log"
+import (
+	"log"
 
-// assert that Logger satisfies grpclog.LoggerV2
+	"google.golang.org/grpc/grpclog"
+)
+
+// assert that "discardLogger" satisfy "Logger" interface
 var _ Logger = &discardLogger{}
 
 // NewDiscardLogger returns a new Logger that discards everything except "fatal".
@@ -39,3 +43,4 @@ func (l *discardLogger) Fatalf(format string, args ...interface{})   { log.Fatal
 func (l *discardLogger) V(lvl int) bool {
 	return false
 }
+func (l *discardLogger) Lvl(lvl int) grpclog.LoggerV2 { return l }

pkg/logger/logger.go

@@ -17,6 +17,47 @@ package logger
 import "google.golang.org/grpc/grpclog"
 
 // Logger defines logging interface.
-// TODO: add "Lvl(lvl int)" for clientv3 loggers.
-// TODO: make this settable with "Set" method.
-type Logger grpclog.LoggerV2
+type Logger interface {
+	grpclog.LoggerV2
+
+	// Lvl returns logger if logger's verbosity level >= "lvl".
+	// Otherwise, logger that discards everything.
+	Lvl(lvl int) grpclog.LoggerV2
+}
+
+// assert that "defaultLogger" satisfy "Logger" interface
+var _ Logger = &defaultLogger{}
+
+// New wraps "grpclog.LoggerV2" that implements "Logger" interface.
+//
+// For example:
+//
+//  var defaultLogger Logger
+//  g := grpclog.NewLoggerV2WithVerbosity(os.Stderr, os.Stderr, os.Stderr, 4)
+//  defaultLogger = New(g)
+//
+func New(g grpclog.LoggerV2) Logger { return &defaultLogger{g: g} }
+
+type defaultLogger struct {
+	g grpclog.LoggerV2
+}
+
+func (l *defaultLogger) Info(args ...interface{})                    { l.g.Info(args...) }
+func (l *defaultLogger) Infoln(args ...interface{})                  { l.g.Info(args...) }
+func (l *defaultLogger) Infof(format string, args ...interface{})    { l.g.Infof(format, args...) }
+func (l *defaultLogger) Warning(args ...interface{})                 { l.g.Warning(args...) }
+func (l *defaultLogger) Warningln(args ...interface{})               { l.g.Warning(args...) }
+func (l *defaultLogger) Warningf(format string, args ...interface{}) { l.g.Warningf(format, args...) }
+func (l *defaultLogger) Error(args ...interface{})                   { l.g.Error(args...) }
+func (l *defaultLogger) Errorln(args ...interface{})                 { l.g.Error(args...) }
+func (l *defaultLogger) Errorf(format string, args ...interface{})   { l.g.Errorf(format, args...) }
+func (l *defaultLogger) Fatal(args ...interface{})                   { l.g.Fatal(args...) }
+func (l *defaultLogger) Fatalln(args ...interface{})                 { l.g.Fatal(args...) }
+func (l *defaultLogger) Fatalf(format string, args ...interface{})   { l.g.Fatalf(format, args...) }
+func (l *defaultLogger) V(lvl int) bool                              { return l.g.V(lvl) }
+func (l *defaultLogger) Lvl(lvl int) grpclog.LoggerV2 {
+	if l.g.V(lvl) {
+		return l
+	}
+	return &discardLogger{}
+}

clientv3/logger_test.go → pkg/logger/logger_test.go

@@ -12,7 +12,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-package clientv3
+package logger_test
 
 import (
 	"bytes"
@@ -20,13 +20,15 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/coreos/etcd/pkg/logger"
+
 	"google.golang.org/grpc/grpclog"
 )
 
 func TestLogger(t *testing.T) {
 	buf := new(bytes.Buffer)
 
-	l := NewLogger(grpclog.NewLoggerV2WithVerbosity(buf, buf, buf, 10))
+	l := logger.New(grpclog.NewLoggerV2WithVerbosity(buf, buf, buf, 10))
 	l.Infof("hello world!")
 	if !strings.Contains(buf.String(), "hello world!") {
 		t.Fatalf("expected 'hello world!', got %q", buf.String())
@@ -43,7 +45,7 @@ func TestLogger(t *testing.T) {
 	}
 	buf.Reset()
 
-	l = NewLogger(grpclog.NewLoggerV2(ioutil.Discard, ioutil.Discard, ioutil.Discard))
+	l = logger.New(grpclog.NewLoggerV2(ioutil.Discard, ioutil.Discard, ioutil.Discard))
 	l.Infof("ignore this")
 	if len(buf.Bytes()) > 0 {
 		t.Fatalf("unexpected logs %q", buf.String())

pkg/logger/package_logger.go

@@ -14,9 +14,12 @@
 
 package logger
 
-import "github.com/coreos/pkg/capnslog"
+import (
+	"github.com/coreos/pkg/capnslog"
+	"google.golang.org/grpc/grpclog"
+)
 
-// assert that Logger satisfies grpclog.LoggerV2
+// assert that "packageLogger" satisfy "Logger" interface
 var _ Logger = &packageLogger{}
 
 // NewPackageLogger wraps "*capnslog.PackageLogger" that implements "Logger" interface.
@@ -24,10 +27,11 @@ var _ Logger = &packageLogger{}
 // For example:
 //
 //  var defaultLogger Logger
-//  plog := capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot")
-//  defaultLogger = NewPackageLogger(plog)
+//  defaultLogger = NewPackageLogger("github.com/coreos/etcd", "snapshot")
 //
-func NewPackageLogger(p *capnslog.PackageLogger) Logger { return &packageLogger{p: p} }
+func NewPackageLogger(repo, pkg string) Logger {
+	return &packageLogger{p: capnslog.NewPackageLogger(repo, pkg)}
+}
 
 type packageLogger struct {
 	p *capnslog.PackageLogger
@@ -48,3 +52,9 @@ func (l *packageLogger) Fatalf(format string, args ...interface{})   { l.p.Fatal
 func (l *packageLogger) V(lvl int) bool {
 	return l.p.LevelAt(capnslog.LogLevel(lvl))
 }
+func (l *packageLogger) Lvl(lvl int) grpclog.LoggerV2 {
+	if l.p.LevelAt(capnslog.LogLevel(lvl)) {
+		return l
+	}
+	return &discardLogger{}
+}

pkg/logger/package_logger_test.go

@@ -0,0 +1,59 @@
+// Copyright 2017 The etcd Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package logger_test
+
+import (
+	"bytes"
+	"io/ioutil"
+	"strings"
+	"testing"
+
+	"github.com/coreos/pkg/capnslog"
+
+	"github.com/coreos/etcd/pkg/logger"
+)
+
+func TestPackageLogger(t *testing.T) {
+	buf := new(bytes.Buffer)
+	capnslog.SetFormatter(capnslog.NewDefaultFormatter(buf))
+
+	l := logger.NewPackageLogger("github.com/coreos/etcd", "logger")
+
+	r := capnslog.MustRepoLogger("github.com/coreos/etcd")
+	r.SetLogLevel(map[string]capnslog.LogLevel{"logger": capnslog.INFO})
+
+	l.Infof("hello world!")
+	if !strings.Contains(buf.String(), "hello world!") {
+		t.Fatalf("expected 'hello world!', got %q", buf.String())
+	}
+	buf.Reset()
+
+	// capnslog.INFO is 3
+	l.Lvl(2).Infof("Level 2")
+	l.Lvl(5).Infof("Level 5")
+	if !strings.Contains(buf.String(), "Level 2") {
+		t.Fatalf("expected 'Level 2', got %q", buf.String())
+	}
+	if strings.Contains(buf.String(), "Level 5") {
+		t.Fatalf("unexpected 'Level 5', got %q", buf.String())
+	}
+	buf.Reset()
+
+	capnslog.SetFormatter(capnslog.NewDefaultFormatter(ioutil.Discard))
+	l.Infof("ignore this")
+	if len(buf.Bytes()) > 0 {
+		t.Fatalf("unexpected logs %q", buf.String())
+	}
+}

snapshot/v3_snapshot_test.go

@@ -29,8 +29,6 @@ import (
 	"github.com/coreos/etcd/pkg/logger"
 	"github.com/coreos/etcd/pkg/testutil"
 	"github.com/coreos/etcd/pkg/types"
-
-	"github.com/coreos/pkg/capnslog"
 )
 
 // TestSnapshotV3RestoreSingle tests single node cluster restoring
@@ -53,7 +51,7 @@ func TestSnapshotV3RestoreSingle(t *testing.T) {
 	cfg.InitialCluster = fmt.Sprintf("%s=%s", cfg.Name, pURLs[0].String())
 	cfg.Dir = filepath.Join(os.TempDir(), fmt.Sprint(time.Now().Nanosecond()))
 
-	sp := NewV3(nil, logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot")))
+	sp := NewV3(nil, logger.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
 
 	err := sp.Restore(dbPath, RestoreConfig{})
 	if err.Error() != `couldn't find local name "" in the initial cluster configuration` {
@@ -190,7 +188,7 @@ func createSnapshotFile(t *testing.T, kvs []kv) string {
 		}
 	}
 
-	sp := NewV3(cli, logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot")))
+	sp := NewV3(cli, logger.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
 	dpPath := filepath.Join(os.TempDir(), fmt.Sprintf("snapshot%d.db", time.Now().Nanosecond()))
 	if err = sp.Save(context.Background(), dpPath); err != nil {
 		t.Fatal(err)
@@ -231,7 +229,7 @@ func restoreCluster(t *testing.T, clusterN int, dbPath string) (
 		cfg.InitialCluster = ics
 		cfg.Dir = filepath.Join(os.TempDir(), fmt.Sprint(time.Now().Nanosecond()+i))
 
-		sp := NewV3(nil, logger.NewPackageLogger(capnslog.NewPackageLogger("github.com/coreos/etcd", "snapshot")))
+		sp := NewV3(nil, logger.NewPackageLogger("github.com/coreos/etcd", "snapshot"))
 		if err := sp.Restore(dbPath, RestoreConfig{
 			Name:                cfg.Name,
 			OutputDataDir:       cfg.Dir,