Merge pull request #9682 from gyuho/zzz

*: support structured logging in v2 auth/http

CHANGELOG-3.4.md

@@ -257,12 +257,12 @@ See [security doc](https://github.com/coreos/etcd/blob/master/Documentation/op-g
   - Again, etcd `Lease` is meant for short-periodic keepalives or sessions, in the range of seconds or minutes. Not for hours or days!
 - Enable etcd server [`raft.Config.CheckQuorum` when starting with `ForceNewCluster`](https://github.com/coreos/etcd/pull/9347).
 
+### Tooling
+
+- Add [`etcd-dump-logs --entry-type`](https://github.com/coreos/etcd/pull/9628) flag to support WAL log filtering by entry type.
+
 ### Go
 
 - Require *Go 1.10+*.
 - Compile with [*Go 1.10.2*](https://golang.org/doc/devel/release.html#go1.10).
 
-### Tooling
-
-- Add [`etcd-dump-logs -entry-type`](https://github.com/coreos/etcd/pull/9628) flag to support WAL log filtering by entry type.
-

embed/etcd.go

@@ -28,8 +28,6 @@ import (
 	"sync"
 	"time"
 
-	"go.uber.org/zap/zapcore"
-
 	"github.com/coreos/etcd/etcdserver"
 	"github.com/coreos/etcd/etcdserver/api/etcdhttp"
 	"github.com/coreos/etcd/etcdserver/api/v2http"
@@ -275,7 +273,7 @@ func (e *Etcd) Config() Config {
 // Client requests will be terminated with request timeout.
 // After timeout, enforce remaning requests be closed immediately.
 func (e *Etcd) Close() {
-	fields := []zapcore.Field{
+	fields := []zap.Field{
 		zap.String("name", e.cfg.Name),
 		zap.String("data-dir", e.cfg.Dir),
 		zap.Strings("advertise-peer-urls", e.cfg.getAPURLs()),
@@ -446,7 +444,7 @@ func configurePeerListeners(cfg *Config) (peers []*peerListener, err error) {
 
 // configure peer handlers after rafthttp.Transport started
 func (e *Etcd) servePeers() (err error) {
-	ph := etcdhttp.NewPeerHandler(e.Server)
+	ph := etcdhttp.NewPeerHandler(e.GetLogger(), e.Server)
 	var peerTLScfg *tls.Config
 	if !e.cfg.PeerTLSInfo.Empty() {
 		if peerTLScfg, err = e.cfg.PeerTLSInfo.ServerConfig(); err != nil {
@@ -635,9 +633,9 @@ func (e *Etcd) serveClients() (err error) {
 	if e.Config().EnableV2 {
 		if len(e.Config().ExperimentalEnableV2V3) > 0 {
 			srv := v2v3.NewServer(e.cfg.logger, v3client.New(e.Server), e.cfg.ExperimentalEnableV2V3)
-			h = v2http.NewClientHandler(srv, e.Server.Cfg.ReqTimeout())
+			h = v2http.NewClientHandler(e.GetLogger(), srv, e.Server.Cfg.ReqTimeout())
 		} else {
-			h = v2http.NewClientHandler(e.Server, e.Server.Cfg.ReqTimeout())
+			h = v2http.NewClientHandler(e.GetLogger(), e.Server, e.Server.Cfg.ReqTimeout())
 		}
 	} else {
 		mux := http.NewServeMux()

etcdmain/grpc_proxy.go

@@ -17,6 +17,7 @@ package etcdmain
 import (
 	"context"
 	"fmt"
+	"io/ioutil"
 	"log"
 	"math"
 	"net"
@@ -388,7 +389,10 @@ func mustHTTPListener(lg *zap.Logger, m cmux.CMux, tlsinfo *transport.TLSInfo, c
 		}
 		lg.Info("gRPC proxy enabled pprof", zap.String("path", debugutil.HTTPPrefixPProf))
 	}
-	srvhttp := &http.Server{Handler: httpmux}
+	srvhttp := &http.Server{
+		Handler:  httpmux,
+		ErrorLog: log.New(ioutil.Discard, "net/http", 0),
+	}
 
 	if tlsinfo == nil {
 		return srvhttp, m.Match(cmux.HTTP1())

etcdserver/api/etcdhttp/base.go

@@ -29,6 +29,7 @@ import (
 	"github.com/coreos/etcd/version"
 
 	"github.com/coreos/pkg/capnslog"
+	"go.uber.org/zap"
 )
 
 var (
@@ -88,13 +89,13 @@ func logHandleFunc(w http.ResponseWriter, r *http.Request) {
 
 	d := json.NewDecoder(r.Body)
 	if err := d.Decode(&in); err != nil {
-		WriteError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid json body"))
+		WriteError(nil, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid json body"))
 		return
 	}
 
 	logl, err := capnslog.ParseLevel(strings.ToUpper(in.Level))
 	if err != nil {
-		WriteError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid log level "+in.Level))
+		WriteError(nil, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid log level "+in.Level))
 		return
 	}
 
@@ -133,27 +134,66 @@ func allowMethod(w http.ResponseWriter, r *http.Request, m string) bool {
 // WriteError logs and writes the given Error to the ResponseWriter
 // If Error is an etcdErr, it is rendered to the ResponseWriter
 // Otherwise, it is assumed to be a StatusInternalServerError
-func WriteError(w http.ResponseWriter, r *http.Request, err error) {
+func WriteError(lg *zap.Logger, w http.ResponseWriter, r *http.Request, err error) {
 	if err == nil {
 		return
 	}
 	switch e := err.(type) {
 	case *v2error.Error:
 		e.WriteTo(w)
+
 	case *httptypes.HTTPError:
 		if et := e.WriteTo(w); et != nil {
-			plog.Debugf("error writing HTTPError (%v) to %s", et, r.RemoteAddr)
+			if lg != nil {
+				lg.Debug(
+					"failed to write v2 HTTP error",
+					zap.String("remote-addr", r.RemoteAddr),
+					zap.String("internal-server-error", e.Error()),
+					zap.Error(et),
+				)
+			} else {
+				plog.Debugf("error writing HTTPError (%v) to %s", et, r.RemoteAddr)
+			}
 		}
+
 	default:
 		switch err {
-		case etcdserver.ErrTimeoutDueToLeaderFail, etcdserver.ErrTimeoutDueToConnectionLost, etcdserver.ErrNotEnoughStartedMembers, etcdserver.ErrUnhealthy:
-			mlog.MergeError(err)
+		case etcdserver.ErrTimeoutDueToLeaderFail, etcdserver.ErrTimeoutDueToConnectionLost, etcdserver.ErrNotEnoughStartedMembers,
+			etcdserver.ErrUnhealthy:
+			if lg != nil {
+				lg.Warn(
+					"v2 response error",
+					zap.String("remote-addr", r.RemoteAddr),
+					zap.String("internal-server-error", err.Error()),
+				)
+			} else {
+				mlog.MergeError(err)
+			}
+
 		default:
-			mlog.MergeErrorf("got unexpected response error (%v)", err)
+			if lg != nil {
+				lg.Warn(
+					"unexpected v2 response error",
+					zap.String("remote-addr", r.RemoteAddr),
+					zap.String("internal-server-error", err.Error()),
+				)
+			} else {
+				mlog.MergeErrorf("got unexpected response error (%v)", err)
+			}
 		}
+
 		herr := httptypes.NewHTTPError(http.StatusInternalServerError, "Internal Server Error")
 		if et := herr.WriteTo(w); et != nil {
-			plog.Debugf("error writing HTTPError (%v) to %s", et, r.RemoteAddr)
+			if lg != nil {
+				lg.Debug(
+					"failed to write v2 HTTP error",
+					zap.String("remote-addr", r.RemoteAddr),
+					zap.String("internal-server-error", err.Error()),
+					zap.Error(et),
+				)
+			} else {
+				plog.Debugf("error writing HTTPError (%v) to %s", et, r.RemoteAddr)
+			}
 		}
 	}
 }

etcdserver/api/etcdhttp/peer.go

@@ -22,19 +22,22 @@ import (
 	"github.com/coreos/etcd/etcdserver/api"
 	"github.com/coreos/etcd/lease/leasehttp"
 	"github.com/coreos/etcd/rafthttp"
+
+	"go.uber.org/zap"
 )
 
 const (
 	peerMembersPrefix = "/members"
 )
 
 // NewPeerHandler generates an http.Handler to handle etcd peer requests.
-func NewPeerHandler(s etcdserver.ServerPeer) http.Handler {
-	return newPeerHandler(s.Cluster(), s.RaftHandler(), s.LeaseHandler())
+func NewPeerHandler(lg *zap.Logger, s etcdserver.ServerPeer) http.Handler {
+	return newPeerHandler(lg, s.Cluster(), s.RaftHandler(), s.LeaseHandler())
 }
 
-func newPeerHandler(cluster api.Cluster, raftHandler http.Handler, leaseHandler http.Handler) http.Handler {
+func newPeerHandler(lg *zap.Logger, cluster api.Cluster, raftHandler http.Handler, leaseHandler http.Handler) http.Handler {
 	mh := &peerMembersHandler{
+		lg:      lg,
 		cluster: cluster,
 	}
 
@@ -52,6 +55,7 @@ func newPeerHandler(cluster api.Cluster, raftHandler http.Handler, leaseHandler
 }
 
 type peerMembersHandler struct {
+	lg      *zap.Logger
 	cluster api.Cluster
 }
 
@@ -68,6 +72,10 @@ func (h *peerMembersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	ms := h.cluster.Members()
 	w.Header().Set("Content-Type", "application/json")
 	if err := json.NewEncoder(w).Encode(ms); err != nil {
-		plog.Warningf("failed to encode members response (%v)", err)
+		if h.lg != nil {
+			h.lg.Warn("failed to encode membership members", zap.Error(err))
+		} else {
+			plog.Warningf("failed to encode members response (%v)", err)
+		}
 	}
 }

etcdserver/api/etcdhttp/peer_test.go

@@ -23,6 +23,8 @@ import (
 	"sort"
 	"testing"
 
+	"go.uber.org/zap"
+
 	"github.com/coreos/etcd/etcdserver/membership"
 	"github.com/coreos/etcd/pkg/testutil"
 	"github.com/coreos/etcd/pkg/types"
@@ -55,7 +57,7 @@ func TestNewPeerHandlerOnRaftPrefix(t *testing.T) {
 	h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		w.Write([]byte("test data"))
 	})
-	ph := newPeerHandler(&fakeCluster{}, h, nil)
+	ph := newPeerHandler(zap.NewExample(), &fakeCluster{}, h, nil)
 	srv := httptest.NewServer(ph)
 	defer srv.Close()