From 98fcd67e9f93a2f04eca60f67d36f46684f6769d Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 10:51:13 -0700 Subject: [PATCH 01/16] etcdserver/v2auth: support structured logging Signed-off-by: Gyuho Lee --- etcdserver/v2auth/auth.go | 138 +++++++++++++++++++++++------ etcdserver/v2auth/auth_requests.go | 29 +++++- etcdserver/v2auth/auth_test.go | 28 +++--- 3 files changed, 154 insertions(+), 41 deletions(-) diff --git a/etcdserver/v2auth/auth.go b/etcdserver/v2auth/auth.go index fe9d228f80d..743bc9907dd 100644 --- a/etcdserver/v2auth/auth.go +++ b/etcdserver/v2auth/auth.go @@ -32,6 +32,7 @@ import ( "github.com/coreos/etcd/pkg/types" "github.com/coreos/pkg/capnslog" + "go.uber.org/zap" "golang.org/x/crypto/bcrypt" ) @@ -98,6 +99,7 @@ type PasswordStore interface { } type store struct { + lg *zap.Logger server doer timeout time.Duration ensuredOnce bool @@ -145,8 +147,9 @@ func authErr(hs int, s string, v ...interface{}) Error { return Error{Status: hs, Errmsg: fmt.Sprintf("auth: "+s, v...)} } -func NewStore(server doer, timeout time.Duration) Store { +func NewStore(lg *zap.Logger, server doer, timeout time.Duration) Store { s := &store{ + lg: lg, server: server, timeout: timeout, PasswordStore: passwordStore{}, @@ -208,7 +211,11 @@ func (s *store) CreateUser(user User) (User, error) { } u, err := s.createUserInternal(user) if err == nil { - plog.Noticef("created user %s", user.User) + if s.lg != nil { + s.lg.Info("created a user", zap.String("user-name", user.User)) + } else { + plog.Noticef("created user %s", user.User) + } } return u, err } @@ -247,7 +254,11 @@ func (s *store) DeleteUser(name string) error { } return err } - plog.Noticef("deleted user %s", name) + if s.lg != nil { + s.lg.Info("deleted a user", zap.String("user-name", name)) + } else { + plog.Noticef("deleted user %s", name) + } return nil } @@ -262,7 +273,7 @@ func (s *store) UpdateUser(user User) (User, error) { return old, err } - newUser, err := old.merge(user, s.PasswordStore) + newUser, err := old.merge(s.lg, user, s.PasswordStore) if err != nil { return old, err } @@ -271,7 +282,11 @@ func (s *store) UpdateUser(user User) (User, error) { } _, err = s.updateResource("/users/"+user.User, newUser) if err == nil { - plog.Noticef("updated user %s", user.User) + if s.lg != nil { + s.lg.Info("updated a user", zap.String("user-name", user.User)) + } else { + plog.Noticef("updated user %s", user.User) + } } return newUser, err } @@ -310,7 +325,11 @@ func (s *store) CreateRole(role Role) error { } } if err == nil { - plog.Noticef("created new role %s", role.Role) + if s.lg != nil { + s.lg.Info("created a new role", zap.String("role-name", role.Role)) + } else { + plog.Noticef("created new role %s", role.Role) + } } return err } @@ -328,7 +347,11 @@ func (s *store) DeleteRole(name string) error { } } if err == nil { - plog.Noticef("deleted role %s", name) + if s.lg != nil { + s.lg.Info("delete a new role", zap.String("role-name", name)) + } else { + plog.Noticef("deleted role %s", name) + } } return err } @@ -346,7 +369,7 @@ func (s *store) UpdateRole(role Role) (Role, error) { } return old, err } - newRole, err := old.merge(role) + newRole, err := old.merge(s.lg, role) if err != nil { return old, err } @@ -355,7 +378,11 @@ func (s *store) UpdateRole(role Role) (Role, error) { } _, err = s.updateResource("/roles/"+role.Role, newRole) if err == nil { - plog.Noticef("updated role %s", role.Role) + if s.lg != nil { + s.lg.Info("updated a new role", zap.String("role-name", role.Role)) + } else { + plog.Noticef("updated role %s", role.Role) + } } return newRole, err } @@ -373,19 +400,42 @@ func (s *store) EnableAuth() error { return authErr(http.StatusConflict, "No root user available, please create one") } if _, err := s.getRole(GuestRoleName, true); err != nil { - plog.Printf("no guest role access found, creating default") + if s.lg != nil { + s.lg.Info( + "no guest role access found; creating default", + zap.String("role-name", GuestRoleName), + ) + } else { + plog.Printf("no guest role access found, creating default") + } if err := s.CreateRole(guestRole); err != nil { - plog.Errorf("error creating guest role. aborting auth enable.") + if s.lg != nil { + s.lg.Warn( + "failed to create a guest role; aborting auth enable", + zap.String("role-name", GuestRoleName), + zap.Error(err), + ) + } else { + plog.Errorf("error creating guest role. aborting auth enable.") + } return err } } if err := s.enableAuth(); err != nil { - plog.Errorf("error enabling auth (%v)", err) + if s.lg != nil { + s.lg.Warn("failed to enable auth", zap.Error(err)) + } else { + plog.Errorf("error enabling auth (%v)", err) + } return err } - plog.Noticef("auth: enabled auth") + if s.lg != nil { + s.lg.Info("enabled auth") + } else { + plog.Noticef("auth: enabled auth") + } return nil } @@ -396,9 +446,17 @@ func (s *store) DisableAuth() error { err := s.disableAuth() if err == nil { - plog.Noticef("auth: disabled auth") + if s.lg != nil { + s.lg.Info("disabled auth") + } else { + plog.Noticef("auth: disabled auth") + } } else { - plog.Errorf("error disabling auth (%v)", err) + if s.lg != nil { + s.lg.Warn("failed to disable auth", zap.Error(err)) + } else { + plog.Errorf("error disabling auth (%v)", err) + } } return err } @@ -407,7 +465,7 @@ func (s *store) DisableAuth() error { // is called and returns a new User with these modifications applied. Think of // all Users as immutable sets of data. Merge allows you to perform the set // operations (desired grants and revokes) atomically -func (ou User) merge(nu User, s PasswordStore) (User, error) { +func (ou User) merge(lg *zap.Logger, nu User, s PasswordStore) (User, error) { var out User if ou.User != nu.User { return out, authErr(http.StatusConflict, "Merging user data with conflicting usernames: %s %s", ou.User, nu.User) @@ -425,14 +483,30 @@ func (ou User) merge(nu User, s PasswordStore) (User, error) { currentRoles := types.NewUnsafeSet(ou.Roles...) for _, g := range nu.Grant { if currentRoles.Contains(g) { - plog.Noticef("granting duplicate role %s for user %s", g, nu.User) + if lg != nil { + lg.Warn( + "attempted to grant a duplicate role for a user", + zap.String("user-name", nu.User), + zap.String("role-name", g), + ) + } else { + plog.Noticef("granting duplicate role %s for user %s", g, nu.User) + } return User{}, authErr(http.StatusConflict, fmt.Sprintf("Granting duplicate role %s for user %s", g, nu.User)) } currentRoles.Add(g) } for _, r := range nu.Revoke { if !currentRoles.Contains(r) { - plog.Noticef("revoking ungranted role %s for user %s", r, nu.User) + if lg != nil { + lg.Warn( + "attempted to revoke a ungranted role for a user", + zap.String("user-name", nu.User), + zap.String("role-name", r), + ) + } else { + plog.Noticef("revoking ungranted role %s for user %s", r, nu.User) + } return User{}, authErr(http.StatusConflict, fmt.Sprintf("Revoking ungranted role %s for user %s", r, nu.User)) } currentRoles.Remove(r) @@ -444,7 +518,7 @@ func (ou User) merge(nu User, s PasswordStore) (User, error) { // merge for a role works the same as User above -- atomic Role application to // each of the substructures. -func (r Role) merge(n Role) (Role, error) { +func (r Role) merge(lg *zap.Logger, n Role) (Role, error) { var out Role var err error if r.Role != n.Role { @@ -455,7 +529,7 @@ func (r Role) merge(n Role) (Role, error) { if err != nil { return out, err } - out.Permissions, err = out.Permissions.Revoke(n.Revoke) + out.Permissions, err = out.Permissions.Revoke(lg, n.Revoke) return out, err } @@ -487,13 +561,13 @@ func (p Permissions) Grant(n *Permissions) (Permissions, error) { // Revoke removes a set of permissions to the permission object on which it is called, // returning a new permission object. -func (p Permissions) Revoke(n *Permissions) (Permissions, error) { +func (p Permissions) Revoke(lg *zap.Logger, n *Permissions) (Permissions, error) { var out Permissions var err error if n == nil { return p, nil } - out.KV, err = p.KV.Revoke(n.KV) + out.KV, err = p.KV.Revoke(lg, n.KV) return out, err } @@ -524,12 +598,19 @@ func (rw RWPermission) Grant(n RWPermission) (RWPermission, error) { // Revoke removes a set of permissions to the permission object on which it is called, // returning a new permission object. -func (rw RWPermission) Revoke(n RWPermission) (RWPermission, error) { +func (rw RWPermission) Revoke(lg *zap.Logger, n RWPermission) (RWPermission, error) { var out RWPermission currentRead := types.NewUnsafeSet(rw.Read...) for _, r := range n.Read { if !currentRead.Contains(r) { - plog.Noticef("revoking ungranted read permission %s", r) + if lg != nil { + lg.Info( + "revoking ungranted read permission", + zap.String("read-permission", r), + ) + } else { + plog.Noticef("revoking ungranted read permission %s", r) + } continue } currentRead.Remove(r) @@ -537,7 +618,14 @@ func (rw RWPermission) Revoke(n RWPermission) (RWPermission, error) { currentWrite := types.NewUnsafeSet(rw.Write...) for _, w := range n.Write { if !currentWrite.Contains(w) { - plog.Noticef("revoking ungranted write permission %s", w) + if lg != nil { + lg.Info( + "revoking ungranted write permission", + zap.String("write-permission", w), + ) + } else { + plog.Noticef("revoking ungranted write permission %s", w) + } continue } currentWrite.Remove(w) diff --git a/etcdserver/v2auth/auth_requests.go b/etcdserver/v2auth/auth_requests.go index 50ef47324cc..8acb26ea73b 100644 --- a/etcdserver/v2auth/auth_requests.go +++ b/etcdserver/v2auth/auth_requests.go @@ -22,6 +22,8 @@ import ( "github.com/coreos/etcd/etcdserver" "github.com/coreos/etcd/etcdserver/etcdserverpb" "github.com/coreos/etcd/etcdserver/v2error" + + "go.uber.org/zap" ) func (s *store) ensureAuthDirectories() error { @@ -45,7 +47,14 @@ func (s *store) ensureAuthDirectories() error { continue } } - plog.Errorf("failed to create auth directories in the store (%v)", err) + if s.lg != nil { + s.lg.Warn( + "failed to create auth directories", + zap.Error(err), + ) + } else { + plog.Errorf("failed to create auth directories in the store (%v)", err) + } return err } } @@ -92,14 +101,28 @@ func (s *store) detectAuth() bool { return false } } - plog.Errorf("failed to detect auth settings (%s)", err) + if s.lg != nil { + s.lg.Warn( + "failed to detect auth settings", + zap.Error(err), + ) + } else { + plog.Errorf("failed to detect auth settings (%s)", err) + } return false } var u bool err = json.Unmarshal([]byte(*value.Event.Node.Value), &u) if err != nil { - plog.Errorf("internal bookkeeping value for enabled isn't valid JSON (%v)", err) + if s.lg != nil { + s.lg.Warn( + "internal bookkeeping value for enabled isn't valid JSON", + zap.Error(err), + ) + } else { + plog.Errorf("internal bookkeeping value for enabled isn't valid JSON (%v)", err) + } return false } return u diff --git a/etcdserver/v2auth/auth_test.go b/etcdserver/v2auth/auth_test.go index 00e674cba08..58f8401d7b4 100644 --- a/etcdserver/v2auth/auth_test.go +++ b/etcdserver/v2auth/auth_test.go @@ -24,6 +24,8 @@ import ( "github.com/coreos/etcd/etcdserver/etcdserverpb" "github.com/coreos/etcd/etcdserver/v2error" "github.com/coreos/etcd/etcdserver/v2store" + + "go.uber.org/zap" ) type fakeDoer struct{} @@ -33,7 +35,7 @@ func (_ fakeDoer) Do(context.Context, etcdserverpb.Request) (etcdserver.Response } func TestCheckPassword(t *testing.T) { - st := NewStore(fakeDoer{}, 5*time.Second) + st := NewStore(zap.NewExample(), fakeDoer{}, 5*time.Second) u := User{Password: "$2a$10$I3iddh1D..EIOXXQtsra4u8AjOtgEa2ERxVvYGfXFBJDo1omXwP.q"} matched := st.CheckPassword(u, "foo") if matched { @@ -95,7 +97,7 @@ func TestMergeUser(t *testing.T) { } for i, tt := range tbl { - out, err := tt.input.merge(tt.merge, passwordStore{}) + out, err := tt.input.merge(zap.NewExample(), tt.merge, passwordStore{}) if err != nil && !tt.iserr { t.Fatalf("Got unexpected error on item %d", i) } @@ -140,7 +142,7 @@ func TestMergeRole(t *testing.T) { }, } for i, tt := range tbl { - out, err := tt.input.merge(tt.merge) + out, err := tt.input.merge(zap.NewExample(), tt.merge) if err != nil && !tt.iserr { t.Fatalf("Got unexpected error on item %d", i) } @@ -220,7 +222,7 @@ func TestAllUsers(t *testing.T) { } expected := []string{"cat", "dog"} - s := store{server: d, timeout: testTimeout, ensuredOnce: false} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: false} users, err := s.AllUsers() if err != nil { t.Error("Unexpected error", err) @@ -248,7 +250,7 @@ func TestGetAndDeleteUser(t *testing.T) { } expected := User{User: "cat", Roles: []string{"animal"}} - s := store{server: d, timeout: testTimeout, ensuredOnce: false} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: false} out, err := s.GetUser("cat") if err != nil { t.Error("Unexpected error", err) @@ -285,7 +287,7 @@ func TestAllRoles(t *testing.T) { } expected := []string{"animal", "human", "root"} - s := store{server: d, timeout: testTimeout, ensuredOnce: false} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: false} out, err := s.AllRoles() if err != nil { t.Error("Unexpected error", err) @@ -313,7 +315,7 @@ func TestGetAndDeleteRole(t *testing.T) { } expected := Role{Role: "animal"} - s := store{server: d, timeout: testTimeout, ensuredOnce: false} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: false} out, err := s.GetRole("animal") if err != nil { t.Error("Unexpected error", err) @@ -360,7 +362,7 @@ func TestEnsure(t *testing.T) { }, } - s := store{server: d, timeout: testTimeout, ensuredOnce: false} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: false} err := s.ensureAuthDirectories() if err != nil { t.Error("Unexpected error", err) @@ -429,7 +431,7 @@ func TestCreateAndUpdateUser(t *testing.T) { update := User{User: "cat", Grant: []string{"pet"}} expected := User{User: "cat", Roles: []string{"animal", "pet"}} - s := store{server: d, timeout: testTimeout, ensuredOnce: true, PasswordStore: fastPasswordStore{}} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: true, PasswordStore: fastPasswordStore{}} out, created, err := s.CreateOrUpdateUser(user) if !created { t.Error("Should have created user, instead updated?") @@ -484,7 +486,7 @@ func TestUpdateRole(t *testing.T) { update := Role{Role: "animal", Grant: &Permissions{KV: RWPermission{Read: []string{}, Write: []string{"/animal"}}}} expected := Role{Role: "animal", Permissions: Permissions{KV: RWPermission{Read: []string{"/animal"}, Write: []string{"/animal"}}}} - s := store{server: d, timeout: testTimeout, ensuredOnce: true} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: true} out, err := s.UpdateRole(update) if err != nil { t.Error("Unexpected error", err) @@ -515,7 +517,7 @@ func TestCreateRole(t *testing.T) { } r := Role{Role: "animal", Permissions: Permissions{KV: RWPermission{Read: []string{"/animal"}, Write: []string{}}}} - s := store{server: d, timeout: testTimeout, ensuredOnce: true} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: true} err := s.CreateRole(Role{Role: "root"}) if err == nil { t.Error("Should error creating root role") @@ -581,7 +583,7 @@ func TestEnableAuth(t *testing.T) { }, explicitlyEnabled: false, } - s := store{server: d, timeout: testTimeout, ensuredOnce: true} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: true} err := s.EnableAuth() if err != nil { t.Error("Unexpected error", err) @@ -625,7 +627,7 @@ func TestDisableAuth(t *testing.T) { }, explicitlyEnabled: false, } - s := store{server: d, timeout: testTimeout, ensuredOnce: true} + s := store{lg: zap.NewExample(), server: d, timeout: testTimeout, ensuredOnce: true} err := s.DisableAuth() if err == nil { t.Error("Expected error; already disabled") From 3b38cb305fa783d1215097a32e1bb3387445403f Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:00:26 -0700 Subject: [PATCH 02/16] etcdserver/api/etcdhttp: support structured logging Signed-off-by: Gyuho Lee --- etcdserver/api/etcdhttp/base.go | 56 ++++++++++++++++++++++++++++----- 1 file changed, 48 insertions(+), 8 deletions(-) diff --git a/etcdserver/api/etcdhttp/base.go b/etcdserver/api/etcdhttp/base.go index 93cd230d01b..f6489c971e9 100644 --- a/etcdserver/api/etcdhttp/base.go +++ b/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) + } } } } From cccf77db9e5cf1ef01015826e1317e5e4cd4385d Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:34:21 -0700 Subject: [PATCH 03/16] etcdserver/api/v2http: support structured logging Signed-off-by: Gyuho Lee --- etcdserver/api/v2http/client.go | 159 ++++++++++---- etcdserver/api/v2http/client_auth.go | 253 ++++++++++++++++------ etcdserver/api/v2http/client_auth_test.go | 13 +- etcdserver/api/v2http/client_test.go | 17 +- etcdserver/api/v2http/http.go | 29 ++- etcdserver/api/v2http/http_test.go | 5 +- 6 files changed, 350 insertions(+), 126 deletions(-) diff --git a/etcdserver/api/v2http/client.go b/etcdserver/api/v2http/client.go index c69a9316b85..e947686609f 100644 --- a/etcdserver/api/v2http/client.go +++ b/etcdserver/api/v2http/client.go @@ -40,6 +40,7 @@ import ( "github.com/coreos/etcd/pkg/types" "github.com/jonboulle/clockwork" + "go.uber.org/zap" ) const ( @@ -51,16 +52,17 @@ const ( ) // NewClientHandler generates a muxed http.Handler with the given parameters to serve etcd client requests. -func NewClientHandler(server etcdserver.ServerPeer, timeout time.Duration) http.Handler { +func NewClientHandler(lg *zap.Logger, server etcdserver.ServerPeer, timeout time.Duration) http.Handler { mux := http.NewServeMux() etcdhttp.HandleBasic(mux, server) - handleV2(mux, server, timeout) - return requestLogger(mux) + handleV2(lg, mux, server, timeout) + return requestLogger(lg, mux) } -func handleV2(mux *http.ServeMux, server etcdserver.ServerV2, timeout time.Duration) { - sec := v2auth.NewStore(server, timeout) +func handleV2(lg *zap.Logger, mux *http.ServeMux, server etcdserver.ServerV2, timeout time.Duration) { + sec := v2auth.NewStore(lg, server, timeout) kh := &keysHandler{ + lg: lg, sec: sec, server: server, cluster: server.Cluster(), @@ -69,10 +71,12 @@ func handleV2(mux *http.ServeMux, server etcdserver.ServerV2, timeout time.Durat } sh := &statsHandler{ + lg: lg, stats: server, } mh := &membersHandler{ + lg: lg, sec: sec, server: server, cluster: server.Cluster(), @@ -84,6 +88,7 @@ func handleV2(mux *http.ServeMux, server etcdserver.ServerV2, timeout time.Durat mah := &machinesHandler{cluster: server.Cluster()} sech := &authHandler{ + lg: lg, sec: sec, cluster: server.Cluster(), clientCertAuthEnabled: server.ClientCertAuthEnabled(), @@ -101,6 +106,7 @@ func handleV2(mux *http.ServeMux, server etcdserver.ServerV2, timeout time.Durat } type keysHandler struct { + lg *zap.Logger sec v2auth.Store server etcdserver.ServerV2 cluster api.Cluster @@ -121,11 +127,11 @@ func (h *keysHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { startTime := clock.Now() rr, noValueOnSuccess, err := parseKeyRequest(r, clock) if err != nil { - writeKeyError(w, err) + writeKeyError(h.lg, w, err) return } // The path must be valid at this point (we've parsed the request successfully). - if !hasKeyPrefixAccess(h.sec, r, r.URL.Path[len(keysPrefix):], rr.Recursive, h.clientCertAuthEnabled) { + if !hasKeyPrefixAccess(h.lg, h.sec, r, r.URL.Path[len(keysPrefix):], rr.Recursive, h.clientCertAuthEnabled) { writeKeyNoAuth(w) return } @@ -135,7 +141,7 @@ func (h *keysHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { resp, err := h.server.Do(ctx, rr) if err != nil { err = trimErrorPrefix(err, etcdserver.StoreKeysPrefix) - writeKeyError(w, err) + writeKeyError(h.lg, w, err) reportRequestFailed(rr, err) return } @@ -143,15 +149,19 @@ func (h *keysHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { case resp.Event != nil: if err := writeKeyEvent(w, resp, noValueOnSuccess); err != nil { // Should never be reached - plog.Errorf("error writing event (%v)", err) + if h.lg != nil { + h.lg.Warn("failed to write key event", zap.Error(err)) + } else { + plog.Errorf("error writing event (%v)", err) + } } reportRequestCompleted(rr, resp, startTime) case resp.Watcher != nil: ctx, cancel := context.WithTimeout(context.Background(), defaultWatchTimeout) defer cancel() - handleKeyWatch(ctx, w, resp, rr.Stream) + handleKeyWatch(ctx, h.lg, w, resp, rr.Stream) default: - writeKeyError(w, errors.New("received response with no Event/Watcher!")) + writeKeyError(h.lg, w, errors.New("received response with no Event/Watcher!")) } } @@ -168,6 +178,7 @@ func (h *machinesHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } type membersHandler struct { + lg *zap.Logger sec v2auth.Store server etcdserver.ServerV2 cluster api.Cluster @@ -180,8 +191,8 @@ func (h *membersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { if !allowMethod(w, r.Method, "GET", "POST", "DELETE", "PUT") { return } - if !hasWriteRootAccess(h.sec, r, h.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasWriteRootAccess(h.lg, h.sec, r, h.clientCertAuthEnabled) { + writeNoAuth(h.lg, w, r) return } w.Header().Set("X-Etcd-Cluster-ID", h.cluster.ID().String()) @@ -196,25 +207,34 @@ func (h *membersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { mc := newMemberCollection(h.cluster.Members()) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(mc); err != nil { - plog.Warningf("failed to encode members response (%v)", err) + if h.lg != nil { + h.lg.Warn("failed to encode members response", zap.Error(err)) + } else { + plog.Warningf("failed to encode members response (%v)", err) + } } case "leader": id := h.server.Leader() if id == 0 { - writeError(w, r, httptypes.NewHTTPError(http.StatusServiceUnavailable, "During election")) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusServiceUnavailable, "During election")) return } m := newMember(h.cluster.Member(id)) w.Header().Set("Content-Type", "application/json") if err := json.NewEncoder(w).Encode(m); err != nil { - plog.Warningf("failed to encode members response (%v)", err) + if h.lg != nil { + h.lg.Warn("failed to encode members response", zap.Error(err)) + } else { + plog.Warningf("failed to encode members response (%v)", err) + } } default: - writeError(w, r, httptypes.NewHTTPError(http.StatusNotFound, "Not found")) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusNotFound, "Not found")) } + case "POST": req := httptypes.MemberCreateRequest{} - if ok := unmarshalRequest(r, &req, w); !ok { + if ok := unmarshalRequest(h.lg, r, &req, w); !ok { return } now := h.clock.Now() @@ -222,43 +242,65 @@ func (h *membersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { _, err := h.server.AddMember(ctx, *m) switch { case err == membership.ErrIDExists || err == membership.ErrPeerURLexists: - writeError(w, r, httptypes.NewHTTPError(http.StatusConflict, err.Error())) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusConflict, err.Error())) return case err != nil: - plog.Errorf("error adding member %s (%v)", m.ID, err) - writeError(w, r, err) + if h.lg != nil { + h.lg.Warn( + "failed to add a member", + zap.String("member-id", m.ID.String()), + zap.Error(err), + ) + } else { + plog.Errorf("error adding member %s (%v)", m.ID, err) + } + writeError(h.lg, w, r, err) return } res := newMember(m) w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusCreated) if err := json.NewEncoder(w).Encode(res); err != nil { - plog.Warningf("failed to encode members response (%v)", err) + if h.lg != nil { + h.lg.Warn("failed to encode members response", zap.Error(err)) + } else { + plog.Warningf("failed to encode members response (%v)", err) + } } + case "DELETE": - id, ok := getID(r.URL.Path, w) + id, ok := getID(h.lg, r.URL.Path, w) if !ok { return } _, err := h.server.RemoveMember(ctx, uint64(id)) switch { case err == membership.ErrIDRemoved: - writeError(w, r, httptypes.NewHTTPError(http.StatusGone, fmt.Sprintf("Member permanently removed: %s", id))) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusGone, fmt.Sprintf("Member permanently removed: %s", id))) case err == membership.ErrIDNotFound: - writeError(w, r, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", id))) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", id))) case err != nil: - plog.Errorf("error removing member %s (%v)", id, err) - writeError(w, r, err) + if h.lg != nil { + h.lg.Warn( + "failed to remove a member", + zap.String("member-id", id.String()), + zap.Error(err), + ) + } else { + plog.Errorf("error removing member %s (%v)", id, err) + } + writeError(h.lg, w, r, err) default: w.WriteHeader(http.StatusNoContent) } + case "PUT": - id, ok := getID(r.URL.Path, w) + id, ok := getID(h.lg, r.URL.Path, w) if !ok { return } req := httptypes.MemberUpdateRequest{} - if ok := unmarshalRequest(r, &req, w); !ok { + if ok := unmarshalRequest(h.lg, r, &req, w); !ok { return } m := membership.Member{ @@ -268,12 +310,20 @@ func (h *membersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { _, err := h.server.UpdateMember(ctx, m) switch { case err == membership.ErrPeerURLexists: - writeError(w, r, httptypes.NewHTTPError(http.StatusConflict, err.Error())) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusConflict, err.Error())) case err == membership.ErrIDNotFound: - writeError(w, r, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", id))) + writeError(h.lg, w, r, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", id))) case err != nil: - plog.Errorf("error updating member %s (%v)", m.ID, err) - writeError(w, r, err) + if h.lg != nil { + h.lg.Warn( + "failed to update a member", + zap.String("member-id", m.ID.String()), + zap.Error(err), + ) + } else { + plog.Errorf("error updating member %s (%v)", m.ID, err) + } + writeError(h.lg, w, r, err) default: w.WriteHeader(http.StatusNoContent) } @@ -281,6 +331,7 @@ func (h *membersHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } type statsHandler struct { + lg *zap.Logger stats stats.Stats } @@ -306,7 +357,7 @@ func (h *statsHandler) serveLeader(w http.ResponseWriter, r *http.Request) { } stats := h.stats.LeaderStats() if stats == nil { - etcdhttp.WriteError(w, r, httptypes.NewHTTPError(http.StatusForbidden, "not current leader")) + etcdhttp.WriteError(h.lg, w, r, httptypes.NewHTTPError(http.StatusForbidden, "not current leader")) return } w.Header().Set("Content-Type", "application/json") @@ -533,7 +584,7 @@ func writeKeyNoAuth(w http.ResponseWriter) { // writeKeyError logs and writes the given Error to the ResponseWriter. // If Error is not an etcdErr, the error will be converted to an etcd error. -func writeKeyError(w http.ResponseWriter, err error) { +func writeKeyError(lg *zap.Logger, w http.ResponseWriter, err error) { if err == nil { return } @@ -543,16 +594,30 @@ func writeKeyError(w http.ResponseWriter, err error) { default: switch err { case etcdserver.ErrTimeoutDueToLeaderFail, etcdserver.ErrTimeoutDueToConnectionLost: - mlog.MergeError(err) + if lg != nil { + lg.Warn( + "v2 response error", + 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("internal-server-error", err.Error()), + ) + } else { + mlog.MergeErrorf("got unexpected response error (%v)", err) + } } ee := v2error.NewError(v2error.EcodeRaftInternal, err.Error(), 0) ee.WriteTo(w) } } -func handleKeyWatch(ctx context.Context, w http.ResponseWriter, resp etcdserver.Response, stream bool) { +func handleKeyWatch(ctx context.Context, lg *zap.Logger, w http.ResponseWriter, resp etcdserver.Response, stream bool) { wa := resp.Watcher defer wa.Remove() ech := wa.EventChan() @@ -588,7 +653,11 @@ func handleKeyWatch(ctx context.Context, w http.ResponseWriter, resp etcdserver. ev = trimEventPrefix(ev, etcdserver.StoreKeysPrefix) if err := json.NewEncoder(w).Encode(ev); err != nil { // Should never be reached - plog.Warningf("error writing event (%v)", err) + if lg != nil { + lg.Warn("failed to encode event", zap.Error(err)) + } else { + plog.Warningf("error writing event (%v)", err) + } return } if !stream { @@ -628,29 +697,29 @@ func trimErrorPrefix(err error, prefix string) error { return err } -func unmarshalRequest(r *http.Request, req json.Unmarshaler, w http.ResponseWriter) bool { +func unmarshalRequest(lg *zap.Logger, r *http.Request, req json.Unmarshaler, w http.ResponseWriter) bool { ctype := r.Header.Get("Content-Type") semicolonPosition := strings.Index(ctype, ";") if semicolonPosition != -1 { ctype = strings.TrimSpace(strings.ToLower(ctype[0:semicolonPosition])) } if ctype != "application/json" { - writeError(w, r, httptypes.NewHTTPError(http.StatusUnsupportedMediaType, fmt.Sprintf("Bad Content-Type %s, accept application/json", ctype))) + writeError(lg, w, r, httptypes.NewHTTPError(http.StatusUnsupportedMediaType, fmt.Sprintf("Bad Content-Type %s, accept application/json", ctype))) return false } b, err := ioutil.ReadAll(r.Body) if err != nil { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, err.Error())) + writeError(lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, err.Error())) return false } if err := req.UnmarshalJSON(b); err != nil { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, err.Error())) + writeError(lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, err.Error())) return false } return true } -func getID(p string, w http.ResponseWriter) (types.ID, bool) { +func getID(lg *zap.Logger, p string, w http.ResponseWriter) (types.ID, bool) { idStr := trimPrefix(p, membersPrefix) if idStr == "" { http.Error(w, "Method Not Allowed", http.StatusMethodNotAllowed) @@ -658,7 +727,7 @@ func getID(p string, w http.ResponseWriter) (types.ID, bool) { } id, err := types.IDFromString(idStr) if err != nil { - writeError(w, nil, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", idStr))) + writeError(lg, w, nil, httptypes.NewHTTPError(http.StatusNotFound, fmt.Sprintf("No such member: %s", idStr))) return 0, false } return id, true diff --git a/etcdserver/api/v2http/client_auth.go b/etcdserver/api/v2http/client_auth.go index 17f0fe6d54f..5316d5bf4d5 100644 --- a/etcdserver/api/v2http/client_auth.go +++ b/etcdserver/api/v2http/client_auth.go @@ -23,25 +23,32 @@ import ( "github.com/coreos/etcd/etcdserver/api" "github.com/coreos/etcd/etcdserver/api/v2http/httptypes" "github.com/coreos/etcd/etcdserver/v2auth" + + "go.uber.org/zap" ) type authHandler struct { + lg *zap.Logger sec v2auth.Store cluster api.Cluster clientCertAuthEnabled bool } -func hasWriteRootAccess(sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool) bool { +func hasWriteRootAccess(lg *zap.Logger, sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool) bool { if r.Method == "GET" || r.Method == "HEAD" { return true } - return hasRootAccess(sec, r, clientCertAuthEnabled) + return hasRootAccess(lg, sec, r, clientCertAuthEnabled) } -func userFromBasicAuth(sec v2auth.Store, r *http.Request) *v2auth.User { +func userFromBasicAuth(lg *zap.Logger, sec v2auth.Store, r *http.Request) *v2auth.User { username, password, ok := r.BasicAuth() if !ok { - plog.Warningf("auth: malformed basic auth encoding") + if lg != nil { + lg.Warn("malformed basic auth encoding") + } else { + plog.Warningf("auth: malformed basic auth encoding") + } return nil } user, err := sec.GetUser(username) @@ -51,23 +58,39 @@ func userFromBasicAuth(sec v2auth.Store, r *http.Request) *v2auth.User { ok = sec.CheckPassword(user, password) if !ok { - plog.Warningf("auth: incorrect password for user: %s", username) + if lg != nil { + lg.Warn("incorrect password", zap.String("user-name", username)) + } else { + plog.Warningf("auth: incorrect password for user: %s", username) + } return nil } return &user } -func userFromClientCertificate(sec v2auth.Store, r *http.Request) *v2auth.User { +func userFromClientCertificate(lg *zap.Logger, sec v2auth.Store, r *http.Request) *v2auth.User { if r.TLS == nil { return nil } for _, chains := range r.TLS.VerifiedChains { for _, chain := range chains { - plog.Debugf("auth: found common name %s.\n", chain.Subject.CommonName) + if lg != nil { + lg.Debug("found common name", zap.String("common-name", chain.Subject.CommonName)) + } else { + plog.Debugf("auth: found common name %s.\n", chain.Subject.CommonName) + } user, err := sec.GetUser(chain.Subject.CommonName) if err == nil { - plog.Debugf("auth: authenticated user %s by cert common name.", user.User) + if lg != nil { + lg.Debug( + "authenticated a user via common name", + zap.String("user-name", user.User), + zap.String("common-name", chain.Subject.CommonName), + ) + } else { + plog.Debugf("auth: authenticated user %s by cert common name.", user.User) + } return &user } } @@ -75,7 +98,7 @@ func userFromClientCertificate(sec v2auth.Store, r *http.Request) *v2auth.User { return nil } -func hasRootAccess(sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool) bool { +func hasRootAccess(lg *zap.Logger, sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool) bool { if sec == nil { // No store means no auth available, eg, tests. return true @@ -86,12 +109,12 @@ func hasRootAccess(sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool var rootUser *v2auth.User if r.Header.Get("Authorization") == "" && clientCertAuthEnabled { - rootUser = userFromClientCertificate(sec, r) + rootUser = userFromClientCertificate(lg, sec, r) if rootUser == nil { return false } } else { - rootUser = userFromBasicAuth(sec, r) + rootUser = userFromBasicAuth(lg, sec, r) if rootUser == nil { return false } @@ -102,11 +125,21 @@ func hasRootAccess(sec v2auth.Store, r *http.Request, clientCertAuthEnabled bool return true } } - plog.Warningf("auth: user %s does not have the %s role for resource %s.", rootUser.User, v2auth.RootRoleName, r.URL.Path) + + if lg != nil { + lg.Warn( + "a user does not have root role for resource", + zap.String("root-user", rootUser.User), + zap.String("root-role-name", v2auth.RootRoleName), + zap.String("resource-path", r.URL.Path), + ) + } else { + plog.Warningf("auth: user %s does not have the %s role for resource %s.", rootUser.User, v2auth.RootRoleName, r.URL.Path) + } return false } -func hasKeyPrefixAccess(sec v2auth.Store, r *http.Request, key string, recursive, clientCertAuthEnabled bool) bool { +func hasKeyPrefixAccess(lg *zap.Logger, sec v2auth.Store, r *http.Request, key string, recursive, clientCertAuthEnabled bool) bool { if sec == nil { // No store means no auth available, eg, tests. return true @@ -118,13 +151,13 @@ func hasKeyPrefixAccess(sec v2auth.Store, r *http.Request, key string, recursive var user *v2auth.User if r.Header.Get("Authorization") == "" { if clientCertAuthEnabled { - user = userFromClientCertificate(sec, r) + user = userFromClientCertificate(lg, sec, r) } if user == nil { - return hasGuestAccess(sec, r, key) + return hasGuestAccess(lg, sec, r, key) } } else { - user = userFromBasicAuth(sec, r) + user = userFromBasicAuth(lg, sec, r) if user == nil { return false } @@ -144,11 +177,20 @@ func hasKeyPrefixAccess(sec v2auth.Store, r *http.Request, key string, recursive return true } } - plog.Warningf("auth: invalid access for user %s on key %s.", user.User, key) + + if lg != nil { + lg.Warn( + "invalid access for user on key", + zap.String("user-name", user.User), + zap.String("key", key), + ) + } else { + plog.Warningf("auth: invalid access for user %s on key %s.", user.User, key) + } return false } -func hasGuestAccess(sec v2auth.Store, r *http.Request, key string) bool { +func hasGuestAccess(lg *zap.Logger, sec v2auth.Store, r *http.Request, key string) bool { writeAccess := r.Method != "GET" && r.Method != "HEAD" role, err := sec.GetRole(v2auth.GuestRoleName) if err != nil { @@ -157,14 +199,31 @@ func hasGuestAccess(sec v2auth.Store, r *http.Request, key string) bool { if role.HasKeyAccess(key, writeAccess) { return true } - plog.Warningf("auth: invalid access for unauthenticated user on resource %s.", key) + + if lg != nil { + lg.Warn( + "invalid access for a guest role on key", + zap.String("role-name", v2auth.GuestRoleName), + zap.String("key", key), + ) + } else { + plog.Warningf("auth: invalid access for unauthenticated user on resource %s.", key) + } return false } -func writeNoAuth(w http.ResponseWriter, r *http.Request) { +func writeNoAuth(lg *zap.Logger, w http.ResponseWriter, r *http.Request) { herr := httptypes.NewHTTPError(http.StatusUnauthorized, "Insufficient credentials") if err := herr.WriteTo(w); err != nil { - plog.Debugf("error writing HTTPError (%v) to %s", err, r.RemoteAddr) + if lg != nil { + lg.Debug( + "failed to write v2 HTTP error", + zap.String("remote-addr", r.RemoteAddr), + zap.Error(err), + ) + } else { + plog.Debugf("error writing HTTPError (%v) to %s", err, r.RemoteAddr) + } } } @@ -180,8 +239,8 @@ func (sh *authHandler) baseRoles(w http.ResponseWriter, r *http.Request) { if !allowMethod(w, r.Method, "GET") { return } - if !hasRootAccess(sh.sec, r, sh.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasRootAccess(sh.lg, sh.sec, r, sh.clientCertAuthEnabled) { + writeNoAuth(sh.lg, w, r) return } @@ -190,7 +249,7 @@ func (sh *authHandler) baseRoles(w http.ResponseWriter, r *http.Request) { roles, err := sh.sec.AllRoles() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } if roles == nil { @@ -199,7 +258,7 @@ func (sh *authHandler) baseRoles(w http.ResponseWriter, r *http.Request) { err = r.ParseForm() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } @@ -210,7 +269,7 @@ func (sh *authHandler) baseRoles(w http.ResponseWriter, r *http.Request) { var role v2auth.Role role, err = sh.sec.GetRole(roleName) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } rolesCollections.Roles = append(rolesCollections.Roles, role) @@ -218,8 +277,16 @@ func (sh *authHandler) baseRoles(w http.ResponseWriter, r *http.Request) { err = json.NewEncoder(w).Encode(rolesCollections) if err != nil { - plog.Warningf("baseRoles error encoding on %s", r.URL) - writeError(w, r, err) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode base roles", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("baseRoles error encoding on %s", r.URL) + } + writeError(sh.lg, w, r, err) return } } @@ -234,7 +301,7 @@ func (sh *authHandler) handleRoles(w http.ResponseWriter, r *http.Request) { return } if len(pieces) != 3 { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid path")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid path")) return } sh.forRole(w, r, pieces[2]) @@ -244,8 +311,8 @@ func (sh *authHandler) forRole(w http.ResponseWriter, r *http.Request, role stri if !allowMethod(w, r.Method, "GET", "PUT", "DELETE") { return } - if !hasRootAccess(sh.sec, r, sh.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasRootAccess(sh.lg, sh.sec, r, sh.clientCertAuthEnabled) { + writeNoAuth(sh.lg, w, r) return } w.Header().Set("X-Etcd-Cluster-ID", sh.cluster.ID().String()) @@ -255,24 +322,33 @@ func (sh *authHandler) forRole(w http.ResponseWriter, r *http.Request, role stri case "GET": data, err := sh.sec.GetRole(role) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } err = json.NewEncoder(w).Encode(data) if err != nil { - plog.Warningf("forRole error encoding on %s", r.URL) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode a role", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("forRole error encoding on %s", r.URL) + } return } return + case "PUT": var in v2auth.Role err := json.NewDecoder(r.Body).Decode(&in) if err != nil { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid JSON in request body.")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid JSON in request body.")) return } if in.Role != role { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Role JSON name does not match the name in the URL")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Role JSON name does not match the name in the URL")) return } @@ -282,19 +358,19 @@ func (sh *authHandler) forRole(w http.ResponseWriter, r *http.Request, role stri if in.Grant.IsEmpty() && in.Revoke.IsEmpty() { err = sh.sec.CreateRole(in) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } w.WriteHeader(http.StatusCreated) out = in } else { if !in.Permissions.IsEmpty() { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Role JSON contains both permissions and grant/revoke")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Role JSON contains both permissions and grant/revoke")) return } out, err = sh.sec.UpdateRole(in) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } w.WriteHeader(http.StatusOK) @@ -302,14 +378,23 @@ func (sh *authHandler) forRole(w http.ResponseWriter, r *http.Request, role stri err = json.NewEncoder(w).Encode(out) if err != nil { - plog.Warningf("forRole error encoding on %s", r.URL) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode a role", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("forRole error encoding on %s", r.URL) + } return } return + case "DELETE": err := sh.sec.DeleteRole(role) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } } @@ -328,8 +413,8 @@ func (sh *authHandler) baseUsers(w http.ResponseWriter, r *http.Request) { if !allowMethod(w, r.Method, "GET") { return } - if !hasRootAccess(sh.sec, r, sh.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasRootAccess(sh.lg, sh.sec, r, sh.clientCertAuthEnabled) { + writeNoAuth(sh.lg, w, r) return } w.Header().Set("X-Etcd-Cluster-ID", sh.cluster.ID().String()) @@ -337,7 +422,7 @@ func (sh *authHandler) baseUsers(w http.ResponseWriter, r *http.Request) { users, err := sh.sec.AllUsers() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } if users == nil { @@ -346,7 +431,7 @@ func (sh *authHandler) baseUsers(w http.ResponseWriter, r *http.Request) { err = r.ParseForm() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } @@ -355,7 +440,7 @@ func (sh *authHandler) baseUsers(w http.ResponseWriter, r *http.Request) { var user v2auth.User user, err = sh.sec.GetUser(userName) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } @@ -374,8 +459,16 @@ func (sh *authHandler) baseUsers(w http.ResponseWriter, r *http.Request) { err = json.NewEncoder(w).Encode(ucs) if err != nil { - plog.Warningf("baseUsers error encoding on %s", r.URL) - writeError(w, r, err) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode users", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("baseUsers error encoding on %s", r.URL) + } + writeError(sh.lg, w, r, err) return } } @@ -390,7 +483,7 @@ func (sh *authHandler) handleUsers(w http.ResponseWriter, r *http.Request) { return } if len(pieces) != 3 { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid path")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid path")) return } sh.forUser(w, r, pieces[2]) @@ -400,8 +493,8 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri if !allowMethod(w, r.Method, "GET", "PUT", "DELETE") { return } - if !hasRootAccess(sh.sec, r, sh.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasRootAccess(sh.lg, sh.sec, r, sh.clientCertAuthEnabled) { + writeNoAuth(sh.lg, w, r) return } w.Header().Set("X-Etcd-Cluster-ID", sh.cluster.ID().String()) @@ -411,13 +504,13 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri case "GET": u, err := sh.sec.GetUser(user) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } err = r.ParseForm() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } @@ -426,7 +519,7 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri var role v2auth.Role role, err = sh.sec.GetRole(roleName) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } uwr.Roles = append(uwr.Roles, role) @@ -434,19 +527,28 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri err = json.NewEncoder(w).Encode(uwr) if err != nil { - plog.Warningf("forUser error encoding on %s", r.URL) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode roles", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("forUser error encoding on %s", r.URL) + } return } return + case "PUT": var u v2auth.User err := json.NewDecoder(r.Body).Decode(&u) if err != nil { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid JSON in request body.")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "Invalid JSON in request body.")) return } if u.User != user { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "User JSON name does not match the name in the URL")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "User JSON name does not match the name in the URL")) return } @@ -466,18 +568,18 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri } if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } } else { // update case if len(u.Roles) != 0 { - writeError(w, r, httptypes.NewHTTPError(http.StatusBadRequest, "User JSON contains both roles and grant/revoke")) + writeError(sh.lg, w, r, httptypes.NewHTTPError(http.StatusBadRequest, "User JSON contains both roles and grant/revoke")) return } out, err = sh.sec.UpdateUser(u) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } } @@ -492,14 +594,23 @@ func (sh *authHandler) forUser(w http.ResponseWriter, r *http.Request, user stri err = json.NewEncoder(w).Encode(out) if err != nil { - plog.Warningf("forUser error encoding on %s", r.URL) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode a user", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("forUser error encoding on %s", r.URL) + } return } return + case "DELETE": err := sh.sec.DeleteUser(user) if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } } @@ -513,8 +624,8 @@ func (sh *authHandler) enableDisable(w http.ResponseWriter, r *http.Request) { if !allowMethod(w, r.Method, "GET", "PUT", "DELETE") { return } - if !hasWriteRootAccess(sh.sec, r, sh.clientCertAuthEnabled) { - writeNoAuth(w, r) + if !hasWriteRootAccess(sh.lg, sh.sec, r, sh.clientCertAuthEnabled) { + writeNoAuth(sh.lg, w, r) return } w.Header().Set("X-Etcd-Cluster-ID", sh.cluster.ID().String()) @@ -525,18 +636,28 @@ func (sh *authHandler) enableDisable(w http.ResponseWriter, r *http.Request) { jsonDict := enabled{isEnabled} err := json.NewEncoder(w).Encode(jsonDict) if err != nil { - plog.Warningf("error encoding auth state on %s", r.URL) + if sh.lg != nil { + sh.lg.Warn( + "failed to encode a auth state", + zap.String("url", r.URL.String()), + zap.Error(err), + ) + } else { + plog.Warningf("error encoding auth state on %s", r.URL) + } } + case "PUT": err := sh.sec.EnableAuth() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } + case "DELETE": err := sh.sec.DisableAuth() if err != nil { - writeError(w, r, err) + writeError(sh.lg, w, r, err) return } } diff --git a/etcdserver/api/v2http/client_auth_test.go b/etcdserver/api/v2http/client_auth_test.go index 195973fb165..93fc5a40965 100644 --- a/etcdserver/api/v2http/client_auth_test.go +++ b/etcdserver/api/v2http/client_auth_test.go @@ -32,6 +32,8 @@ import ( "github.com/coreos/etcd/etcdserver/api" "github.com/coreos/etcd/etcdserver/v2auth" + + "go.uber.org/zap" ) const goodPassword = "good" @@ -363,6 +365,7 @@ func TestAuthFlow(t *testing.T) { for i, tt := range testCases { mux := http.NewServeMux() h := &authHandler{ + lg: zap.NewExample(), sec: &tt.store, cluster: &fakeCluster{id: 1}, } @@ -750,13 +753,13 @@ func TestPrefixAccess(t *testing.T) { } for i, tt := range table { - if tt.hasRoot != hasRootAccess(tt.store, tt.req, true) { + if tt.hasRoot != hasRootAccess(zap.NewExample(), tt.store, tt.req, true) { t.Errorf("#%d: hasRoot doesn't match (expected %v)", i, tt.hasRoot) } - if tt.hasKeyPrefixAccess != hasKeyPrefixAccess(tt.store, tt.req, tt.key, false, true) { + if tt.hasKeyPrefixAccess != hasKeyPrefixAccess(zap.NewExample(), tt.store, tt.req, tt.key, false, true) { t.Errorf("#%d: hasKeyPrefixAccess doesn't match (expected %v)", i, tt.hasRoot) } - if tt.hasRecursiveAccess != hasKeyPrefixAccess(tt.store, tt.req, tt.key, true, true) { + if tt.hasRecursiveAccess != hasKeyPrefixAccess(zap.NewExample(), tt.store, tt.req, tt.key, true, true) { t.Errorf("#%d: hasRecursiveAccess doesn't match (expected %v)", i, tt.hasRoot) } } @@ -832,7 +835,7 @@ func TestUserFromClientCertificate(t *testing.T) { } for i, tt := range table { - user := userFromClientCertificate(tt.store, tt.req) + user := userFromClientCertificate(zap.NewExample(), tt.store, tt.req) userExists := user != nil if tt.userExists != userExists { @@ -897,7 +900,7 @@ func TestUserFromBasicAuth(t *testing.T) { } for i, tt := range table { - user := userFromBasicAuth(sec, tt.req) + user := userFromBasicAuth(zap.NewExample(), sec, tt.req) userExists := user != nil if tt.userExists != userExists { diff --git a/etcdserver/api/v2http/client_test.go b/etcdserver/api/v2http/client_test.go index 10ee2588294..78fcdcbf438 100644 --- a/etcdserver/api/v2http/client_test.go +++ b/etcdserver/api/v2http/client_test.go @@ -42,6 +42,7 @@ import ( "github.com/coreos/go-semver/semver" "github.com/jonboulle/clockwork" + "go.uber.org/zap" ) func mustMarshalEvent(t *testing.T, ev *v2store.Event) string { @@ -657,6 +658,7 @@ func TestServeMembers(t *testing.T) { members: map[uint64]*membership.Member{1: &memb1, 2: &memb2}, } h := &membersHandler{ + lg: zap.NewExample(), server: &serverRecorder{}, clock: clockwork.NewFakeClock(), cluster: cluster, @@ -710,6 +712,7 @@ func TestServeLeader(t *testing.T) { members: map[uint64]*membership.Member{1: &memb1, 2: &memb2}, } h := &membersHandler{ + lg: zap.NewExample(), server: &serverRecorder{}, clock: clockwork.NewFakeClock(), cluster: cluster, @@ -762,6 +765,7 @@ func TestServeMembersCreate(t *testing.T) { req.Header.Set("Content-Type", "application/json") s := &serverRecorder{} h := &membersHandler{ + lg: zap.NewExample(), server: s, clock: clockwork.NewFakeClock(), cluster: &fakeCluster{id: 1}, @@ -811,6 +815,7 @@ func TestServeMembersDelete(t *testing.T) { } s := &serverRecorder{} h := &membersHandler{ + lg: zap.NewExample(), server: s, cluster: &fakeCluster{id: 1}, } @@ -847,6 +852,7 @@ func TestServeMembersUpdate(t *testing.T) { req.Header.Set("Content-Type", "application/json") s := &serverRecorder{} h := &membersHandler{ + lg: zap.NewExample(), server: s, clock: clockwork.NewFakeClock(), cluster: &fakeCluster{id: 1}, @@ -1139,6 +1145,7 @@ func TestServeMembersFail(t *testing.T) { } for i, tt := range tests { h := &membersHandler{ + lg: zap.NewExample(), server: tt.server, cluster: &fakeCluster{id: 1}, clock: clockwork.NewFakeClock(), @@ -1302,7 +1309,7 @@ func TestGetID(t *testing.T) { for i, tt := range tests { w := httptest.NewRecorder() - id, ok := getID(tt.path, w) + id, ok := getID(zap.NewExample(), tt.path, w) if id != tt.wid { t.Errorf("#%d: id = %d, want %d", i, id, tt.wid) } @@ -1489,6 +1496,7 @@ func TestBadServeKeys(t *testing.T) { } for i, tt := range testBadCases { h := &keysHandler{ + lg: zap.NewExample(), timeout: 0, // context times out immediately server: tt.server, cluster: &fakeCluster{id: 1}, @@ -1547,6 +1555,7 @@ func TestServeKeysGood(t *testing.T) { } for i, tt := range tests { h := &keysHandler{ + lg: zap.NewExample(), timeout: time.Hour, server: server, cluster: &fakeCluster{id: 1}, @@ -1602,6 +1611,7 @@ func TestServeKeysEvent(t *testing.T) { server := &resServer{} h := &keysHandler{ + lg: zap.NewExample(), timeout: time.Hour, server: server, cluster: &fakeCluster{id: 1}, @@ -1644,6 +1654,7 @@ func TestServeKeysWatch(t *testing.T) { }, } h := &keysHandler{ + lg: zap.NewExample(), timeout: time.Hour, server: server, cluster: &fakeCluster{id: 1}, @@ -1771,7 +1782,7 @@ func TestHandleWatch(t *testing.T) { tt.doToChan(wa.echan) resp := etcdserver.Response{Term: 5, Index: 100, Watcher: wa} - handleKeyWatch(tt.getCtx(), rw, resp, false) + handleKeyWatch(tt.getCtx(), zap.NewExample(), rw, resp, false) wcode := http.StatusOK wct := "application/json" @@ -1816,7 +1827,7 @@ func TestHandleWatchStreaming(t *testing.T) { done := make(chan struct{}) go func() { resp := etcdserver.Response{Watcher: wa} - handleKeyWatch(ctx, rw, resp, true) + handleKeyWatch(ctx, zap.NewExample(), rw, resp, true) close(done) }() diff --git a/etcdserver/api/v2http/http.go b/etcdserver/api/v2http/http.go index 8719a2d397a..fc1f5894a1a 100644 --- a/etcdserver/api/v2http/http.go +++ b/etcdserver/api/v2http/http.go @@ -26,6 +26,7 @@ import ( "github.com/coreos/etcd/pkg/logutil" "github.com/coreos/pkg/capnslog" + "go.uber.org/zap" ) const ( @@ -38,18 +39,27 @@ var ( mlog = logutil.NewMergeLogger(plog) ) -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 } if e, ok := err.(v2auth.Error); ok { herr := httptypes.NewHTTPError(e.HTTPStatus(), e.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("v2auth-error", e.Error()), + zap.Error(et), + ) + } else { + plog.Debugf("error writing HTTPError (%v) to %s", et, r.RemoteAddr) + } } return } - etcdhttp.WriteError(w, r, err) + etcdhttp.WriteError(lg, w, r, err) } // allowMethod verifies that the given method is one of the allowed methods, @@ -66,9 +76,18 @@ func allowMethod(w http.ResponseWriter, m string, ms ...string) bool { return false } -func requestLogger(handler http.Handler) http.Handler { +func requestLogger(lg *zap.Logger, handler http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - plog.Debugf("[%s] %s remote:%s", r.Method, r.RequestURI, r.RemoteAddr) + if lg != nil { + lg.Debug( + "handling HTTP request", + zap.String("method", r.Method), + zap.String("request-uri", r.RequestURI), + zap.String("remote-addr", r.RemoteAddr), + ) + } else { + plog.Debugf("[%s] %s remote:%s", r.Method, r.RequestURI, r.RemoteAddr) + } handler.ServeHTTP(w, r) }) } diff --git a/etcdserver/api/v2http/http_test.go b/etcdserver/api/v2http/http_test.go index 679254577c0..30e1945f717 100644 --- a/etcdserver/api/v2http/http_test.go +++ b/etcdserver/api/v2http/http_test.go @@ -30,6 +30,7 @@ import ( "github.com/coreos/etcd/raft/raftpb" "github.com/coreos/go-semver/semver" + "go.uber.org/zap" ) type fakeCluster struct { @@ -78,7 +79,7 @@ func TestWriteError(t *testing.T) { // nil error should not panic rec := httptest.NewRecorder() r := new(http.Request) - writeError(rec, r, nil) + writeError(zap.NewExample(), rec, r, nil) h := rec.Header() if len(h) > 0 { t.Fatalf("unexpected non-empty headers: %#v", h) @@ -111,7 +112,7 @@ func TestWriteError(t *testing.T) { for i, tt := range tests { rw := httptest.NewRecorder() - writeError(rw, r, tt.err) + writeError(zap.NewExample(), rw, r, tt.err) if code := rw.Code; code != tt.wcode { t.Errorf("#%d: code=%d, want %d", i, code, tt.wcode) } From 26b0c84d29b8ec3f5d0b0e4ea1d1c32907421173 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:34:43 -0700 Subject: [PATCH 04/16] embed: support structured logging in "v2http" Signed-off-by: Gyuho Lee --- embed/etcd.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/embed/etcd.go b/embed/etcd.go index 8d537800ce1..3481bfbaa45 100644 --- a/embed/etcd.go +++ b/embed/etcd.go @@ -635,9 +635,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() From d2e14847628b6c54c3cdbbe733da0c71a908a6d3 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:35:00 -0700 Subject: [PATCH 05/16] integration: support structured logging in "v2http" Signed-off-by: Gyuho Lee --- integration/cluster.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/integration/cluster.go b/integration/cluster.go index 81f47cf72a2..7dba9f26ff5 100644 --- a/integration/cluster.go +++ b/integration/cluster.go @@ -839,7 +839,13 @@ func (m *member) Launch() error { for _, ln := range m.ClientListeners { hs := &httptest.Server{ Listener: ln, - Config: &http.Server{Handler: v2http.NewClientHandler(m.s, m.ServerConfig.ReqTimeout())}, + Config: &http.Server{ + Handler: v2http.NewClientHandler( + m.Logger, + m.s, + m.ServerConfig.ReqTimeout(), + ), + }, } if m.ClientTLSInfo == nil { hs.Start() From 4d863dac5ac45ebc5a28c30aaff14f362faf9534 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:42:34 -0700 Subject: [PATCH 06/16] mvcc: support structured logging in compact restore Signed-off-by: Gyuho Lee --- mvcc/kvstore.go | 35 ++++++++++++++++++++++++++++++++--- 1 file changed, 32 insertions(+), 3 deletions(-) diff --git a/mvcc/kvstore.go b/mvcc/kvstore.go index 832de9e35d5..1b46ce4b1f1 100644 --- a/mvcc/kvstore.go +++ b/mvcc/kvstore.go @@ -18,6 +18,7 @@ import ( "context" "encoding/binary" "errors" + "fmt" "hash/crc32" "math" "sync" @@ -330,7 +331,17 @@ func (s *store) restore() error { _, finishedCompactBytes := tx.UnsafeRange(metaBucketName, finishedCompactKeyName, nil, 0) if len(finishedCompactBytes) != 0 { s.compactMainRev = bytesToRev(finishedCompactBytes[0]).main - plog.Printf("restore compact to %d", s.compactMainRev) + + if s.lg != nil { + s.lg.Info( + "restored last compact revision", + zap.String("meta-bucket-name", string(metaBucketName)), + zap.String("meta-bucket-name-key", string(finishedCompactKeyName)), + zap.Int64("restored-compact-revision", s.compactMainRev), + ) + } else { + plog.Printf("restore compact to %d", s.compactMainRev) + } } _, scheduledCompactBytes := tx.UnsafeRange(metaBucketName, scheduledCompactKeyName, nil, 0) scheduledCompact := int64(0) @@ -377,7 +388,15 @@ func (s *store) restore() error { } err := s.le.Attach(lid, []lease.LeaseItem{{Key: key}}) if err != nil { - plog.Errorf("unexpected Attach error: %v", err) + if s.lg != nil { + s.lg.Warn( + "failed to attach a lease", + zap.String("lease-id", fmt.Sprintf("%016x", lid)), + zap.Error(err), + ) + } else { + plog.Errorf("unexpected Attach error: %v", err) + } } } @@ -385,7 +404,17 @@ func (s *store) restore() error { if scheduledCompact != 0 { s.Compact(scheduledCompact) - plog.Printf("resume scheduled compaction at %d", scheduledCompact) + + if s.lg != nil { + s.lg.Info( + "resume scheduled compaction", + zap.String("meta-bucket-name", string(metaBucketName)), + zap.String("meta-bucket-name-key", string(scheduledCompactKeyName)), + zap.Int64("scheduled-compact-revision", scheduledCompact), + ) + } else { + plog.Printf("resume scheduled compaction at %d", scheduledCompact) + } } return nil From c60054abea34930ffa72620eb20cda56ec9f3e5f Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:53:28 -0700 Subject: [PATCH 07/16] etcdserver/api/etcdhttp: use structured logging in peer handler Signed-off-by: Gyuho Lee --- etcdserver/api/etcdhttp/peer.go | 16 ++++++++++++---- etcdserver/api/etcdhttp/peer_test.go | 4 +++- 2 files changed, 15 insertions(+), 5 deletions(-) diff --git a/etcdserver/api/etcdhttp/peer.go b/etcdserver/api/etcdhttp/peer.go index 0a9213b01a9..6b533730a8c 100644 --- a/etcdserver/api/etcdhttp/peer.go +++ b/etcdserver/api/etcdhttp/peer.go @@ -22,6 +22,8 @@ import ( "github.com/coreos/etcd/etcdserver/api" "github.com/coreos/etcd/lease/leasehttp" "github.com/coreos/etcd/rafthttp" + + "go.uber.org/zap" ) const ( @@ -29,12 +31,13 @@ const ( ) // 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) + } } } diff --git a/etcdserver/api/etcdhttp/peer_test.go b/etcdserver/api/etcdhttp/peer_test.go index 40dbef8ae34..ad48f14784d 100644 --- a/etcdserver/api/etcdhttp/peer_test.go +++ b/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() From 154d7ca4f286ed92095d59625137b978d2624001 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:53:46 -0700 Subject: [PATCH 08/16] embed: use structured logging in peer handler Signed-off-by: Gyuho Lee --- embed/etcd.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/embed/etcd.go b/embed/etcd.go index 3481bfbaa45..1206a8882f8 100644 --- a/embed/etcd.go +++ b/embed/etcd.go @@ -446,7 +446,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 { From 58b7ab97eb9d82046c9257a1235c4701450ac6db Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:53:56 -0700 Subject: [PATCH 09/16] integration: use structured logging in peer handler Signed-off-by: Gyuho Lee --- integration/cluster.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/integration/cluster.go b/integration/cluster.go index 7dba9f26ff5..70a530ed6d3 100644 --- a/integration/cluster.go +++ b/integration/cluster.go @@ -786,7 +786,7 @@ func (m *member) Launch() error { go m.grpcServer.Serve(m.grpcListener) } - m.raftHandler = &testutil.PauseableHandler{Next: etcdhttp.NewPeerHandler(m.s)} + m.raftHandler = &testutil.PauseableHandler{Next: etcdhttp.NewPeerHandler(m.Logger, m.s)} h := (http.Handler)(m.raftHandler) if m.grpcListener != nil { From 1d18f45caf338a1e98b68103f31781d7cf051ee6 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:58:56 -0700 Subject: [PATCH 10/16] integration: silence http server logs Signed-off-by: Gyuho Lee --- integration/cluster.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/integration/cluster.go b/integration/cluster.go index 70a530ed6d3..65afa05686d 100644 --- a/integration/cluster.go +++ b/integration/cluster.go @@ -19,6 +19,7 @@ import ( "crypto/tls" "fmt" "io/ioutil" + "log" "math/rand" "net" "net/http" @@ -818,8 +819,12 @@ func (m *member) Launch() error { } hs := &httptest.Server{ Listener: ll, - Config: &http.Server{Handler: h, TLSConfig: peerTLScfg}, - TLS: peerTLScfg, + Config: &http.Server{ + Handler: h, + TLSConfig: peerTLScfg, + ErrorLog: log.New(ioutil.Discard, "net/http", 0), + }, + TLS: peerTLScfg, } hs.Start() @@ -845,6 +850,7 @@ func (m *member) Launch() error { m.s, m.ServerConfig.ReqTimeout(), ), + ErrorLog: log.New(ioutil.Discard, "net/http", 0), }, } if m.ClientTLSInfo == nil { From e7e31e952953a56a1cb5b775e1cf2a0cdb2a9d2b Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:59:08 -0700 Subject: [PATCH 11/16] functional: silence http server logs Signed-off-by: Gyuho Lee --- functional/cmd/etcd-proxy/main.go | 7 +++++-- functional/tester/cluster.go | 6 ++++-- 2 files changed, 9 insertions(+), 4 deletions(-) diff --git a/functional/cmd/etcd-proxy/main.go b/functional/cmd/etcd-proxy/main.go index 24c275e8e7f..85b56b9e1b1 100644 --- a/functional/cmd/etcd-proxy/main.go +++ b/functional/cmd/etcd-proxy/main.go @@ -19,6 +19,8 @@ import ( "context" "flag" "fmt" + "io/ioutil" + "log" "net/http" "net/url" "os" @@ -191,8 +193,9 @@ $ ETCDCTL_API=3 ./bin/etcdctl --endpoints localhost:23790 put foo bar`) } }) srv := &http.Server{ - Addr: fmt.Sprintf(":%d", httpPort), - Handler: mux, + Addr: fmt.Sprintf(":%d", httpPort), + Handler: mux, + ErrorLog: log.New(ioutil.Discard, "net/http", 0), } defer srv.Close() diff --git a/functional/tester/cluster.go b/functional/tester/cluster.go index b18084d48ef..e0d19f769cb 100644 --- a/functional/tester/cluster.go +++ b/functional/tester/cluster.go @@ -20,6 +20,7 @@ import ( "fmt" "io" "io/ioutil" + "log" "math/rand" "net/http" "net/url" @@ -106,8 +107,9 @@ func NewCluster(lg *zap.Logger, fpath string) (*Cluster, error) { } } clus.testerHTTPServer = &http.Server{ - Addr: clus.Tester.Addr, - Handler: mux, + Addr: clus.Tester.Addr, + Handler: mux, + ErrorLog: log.New(ioutil.Discard, "net/http", 0), } go clus.serveTesterServer() From 7da365bd45816b3a547b3b3d70566b9687752a86 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:59:17 -0700 Subject: [PATCH 12/16] etcdmain: silence http server logs Signed-off-by: Gyuho Lee --- etcdmain/grpc_proxy.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/etcdmain/grpc_proxy.go b/etcdmain/grpc_proxy.go index 6a1ff1f6bec..aad8a088e40 100644 --- a/etcdmain/grpc_proxy.go +++ b/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()) From 3ed6c967ceec5ae871bc89601fcd9cee59bb92ed Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 12:59:29 -0700 Subject: [PATCH 13/16] pkg/proxy: silence http server logs Signed-off-by: Gyuho Lee --- pkg/proxy/server_test.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/pkg/proxy/server_test.go b/pkg/proxy/server_test.go index ace1a7eeb62..d9db223efa1 100644 --- a/pkg/proxy/server_test.go +++ b/pkg/proxy/server_test.go @@ -19,6 +19,7 @@ import ( "crypto/tls" "fmt" "io/ioutil" + "log" "math/rand" "net" "net/http" @@ -485,6 +486,7 @@ func testServerHTTP(t *testing.T, secure, delayTx bool) { Addr: dstAddr, Handler: mux, TLSConfig: tlsConfig, + ErrorLog: log.New(ioutil.Discard, "net/http", 0), } donec := make(chan struct{}) From 44385bc7b9d483d3f56f2d98c630da4766c10bfc Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 13:25:31 -0700 Subject: [PATCH 14/16] vendor: upgrade "go.uber.org/zap" to v1.8.0 Signed-off-by: Gyuho Lee --- Gopkg.lock | 4 +- vendor/go.uber.org/zap/array.go | 46 +++++----- vendor/go.uber.org/zap/buffer/buffer.go | 2 +- vendor/go.uber.org/zap/config.go | 2 +- vendor/go.uber.org/zap/error.go | 6 +- vendor/go.uber.org/zap/field.go | 112 ++++++++++++------------ vendor/go.uber.org/zap/global.go | 80 +++++++++++------ vendor/go.uber.org/zap/level.go | 2 +- vendor/go.uber.org/zap/logger.go | 16 ++-- vendor/go.uber.org/zap/options.go | 2 +- vendor/go.uber.org/zap/sugar.go | 12 +-- 11 files changed, 159 insertions(+), 125 deletions(-) diff --git a/Gopkg.lock b/Gopkg.lock index 87f3ab5f839..b094678561d 100644 --- a/Gopkg.lock +++ b/Gopkg.lock @@ -251,8 +251,8 @@ "internal/exit", "zapcore" ] - revision = "35aad584952c3e7020db7b839f6b102de6271f89" - version = "v1.7.1" + revision = "eeedf312bc6c57391d84767a4cd413f02a917974" + version = "v1.8.0" [[projects]] name = "golang.org/x/crypto" diff --git a/vendor/go.uber.org/zap/array.go b/vendor/go.uber.org/zap/array.go index 3d4d49f4718..5be3704a3e1 100644 --- a/vendor/go.uber.org/zap/array.go +++ b/vendor/go.uber.org/zap/array.go @@ -29,113 +29,113 @@ import ( // Array constructs a field with the given key and ArrayMarshaler. It provides // a flexible, but still type-safe and efficient, way to add array-like types // to the logging context. The struct's MarshalLogArray method is called lazily. -func Array(key string, val zapcore.ArrayMarshaler) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.ArrayMarshalerType, Interface: val} +func Array(key string, val zapcore.ArrayMarshaler) Field { + return Field{Key: key, Type: zapcore.ArrayMarshalerType, Interface: val} } // Bools constructs a field that carries a slice of bools. -func Bools(key string, bs []bool) zapcore.Field { +func Bools(key string, bs []bool) Field { return Array(key, bools(bs)) } // ByteStrings constructs a field that carries a slice of []byte, each of which // must be UTF-8 encoded text. -func ByteStrings(key string, bss [][]byte) zapcore.Field { +func ByteStrings(key string, bss [][]byte) Field { return Array(key, byteStringsArray(bss)) } // Complex128s constructs a field that carries a slice of complex numbers. -func Complex128s(key string, nums []complex128) zapcore.Field { +func Complex128s(key string, nums []complex128) Field { return Array(key, complex128s(nums)) } // Complex64s constructs a field that carries a slice of complex numbers. -func Complex64s(key string, nums []complex64) zapcore.Field { +func Complex64s(key string, nums []complex64) Field { return Array(key, complex64s(nums)) } // Durations constructs a field that carries a slice of time.Durations. -func Durations(key string, ds []time.Duration) zapcore.Field { +func Durations(key string, ds []time.Duration) Field { return Array(key, durations(ds)) } // Float64s constructs a field that carries a slice of floats. -func Float64s(key string, nums []float64) zapcore.Field { +func Float64s(key string, nums []float64) Field { return Array(key, float64s(nums)) } // Float32s constructs a field that carries a slice of floats. -func Float32s(key string, nums []float32) zapcore.Field { +func Float32s(key string, nums []float32) Field { return Array(key, float32s(nums)) } // Ints constructs a field that carries a slice of integers. -func Ints(key string, nums []int) zapcore.Field { +func Ints(key string, nums []int) Field { return Array(key, ints(nums)) } // Int64s constructs a field that carries a slice of integers. -func Int64s(key string, nums []int64) zapcore.Field { +func Int64s(key string, nums []int64) Field { return Array(key, int64s(nums)) } // Int32s constructs a field that carries a slice of integers. -func Int32s(key string, nums []int32) zapcore.Field { +func Int32s(key string, nums []int32) Field { return Array(key, int32s(nums)) } // Int16s constructs a field that carries a slice of integers. -func Int16s(key string, nums []int16) zapcore.Field { +func Int16s(key string, nums []int16) Field { return Array(key, int16s(nums)) } // Int8s constructs a field that carries a slice of integers. -func Int8s(key string, nums []int8) zapcore.Field { +func Int8s(key string, nums []int8) Field { return Array(key, int8s(nums)) } // Strings constructs a field that carries a slice of strings. -func Strings(key string, ss []string) zapcore.Field { +func Strings(key string, ss []string) Field { return Array(key, stringArray(ss)) } // Times constructs a field that carries a slice of time.Times. -func Times(key string, ts []time.Time) zapcore.Field { +func Times(key string, ts []time.Time) Field { return Array(key, times(ts)) } // Uints constructs a field that carries a slice of unsigned integers. -func Uints(key string, nums []uint) zapcore.Field { +func Uints(key string, nums []uint) Field { return Array(key, uints(nums)) } // Uint64s constructs a field that carries a slice of unsigned integers. -func Uint64s(key string, nums []uint64) zapcore.Field { +func Uint64s(key string, nums []uint64) Field { return Array(key, uint64s(nums)) } // Uint32s constructs a field that carries a slice of unsigned integers. -func Uint32s(key string, nums []uint32) zapcore.Field { +func Uint32s(key string, nums []uint32) Field { return Array(key, uint32s(nums)) } // Uint16s constructs a field that carries a slice of unsigned integers. -func Uint16s(key string, nums []uint16) zapcore.Field { +func Uint16s(key string, nums []uint16) Field { return Array(key, uint16s(nums)) } // Uint8s constructs a field that carries a slice of unsigned integers. -func Uint8s(key string, nums []uint8) zapcore.Field { +func Uint8s(key string, nums []uint8) Field { return Array(key, uint8s(nums)) } // Uintptrs constructs a field that carries a slice of pointer addresses. -func Uintptrs(key string, us []uintptr) zapcore.Field { +func Uintptrs(key string, us []uintptr) Field { return Array(key, uintptrs(us)) } // Errors constructs a field that carries a slice of errors. -func Errors(key string, errs []error) zapcore.Field { +func Errors(key string, errs []error) Field { return Array(key, errArray(errs)) } diff --git a/vendor/go.uber.org/zap/buffer/buffer.go b/vendor/go.uber.org/zap/buffer/buffer.go index ea6fdc8d977..d15f7fdb35b 100644 --- a/vendor/go.uber.org/zap/buffer/buffer.go +++ b/vendor/go.uber.org/zap/buffer/buffer.go @@ -21,7 +21,7 @@ // Package buffer provides a thin wrapper around a byte slice. Unlike the // standard library's bytes.Buffer, it supports a portion of the strconv // package's zero-allocation formatters. -package buffer +package buffer // import "go.uber.org/zap/buffer" import "strconv" diff --git a/vendor/go.uber.org/zap/config.go b/vendor/go.uber.org/zap/config.go index b0658eda0a5..dae130303e7 100644 --- a/vendor/go.uber.org/zap/config.go +++ b/vendor/go.uber.org/zap/config.go @@ -210,7 +210,7 @@ func (cfg Config) buildOptions(errSink zapcore.WriteSyncer) []Option { } if len(cfg.InitialFields) > 0 { - fs := make([]zapcore.Field, 0, len(cfg.InitialFields)) + fs := make([]Field, 0, len(cfg.InitialFields)) keys := make([]string, 0, len(cfg.InitialFields)) for k := range cfg.InitialFields { keys = append(keys, k) diff --git a/vendor/go.uber.org/zap/error.go b/vendor/go.uber.org/zap/error.go index 2bff30d8584..65982a51e54 100644 --- a/vendor/go.uber.org/zap/error.go +++ b/vendor/go.uber.org/zap/error.go @@ -31,7 +31,7 @@ var _errArrayElemPool = sync.Pool{New: func() interface{} { }} // Error is shorthand for the common idiom NamedError("error", err). -func Error(err error) zapcore.Field { +func Error(err error) Field { return NamedError("error", err) } @@ -42,11 +42,11 @@ func Error(err error) zapcore.Field { // // For the common case in which the key is simply "error", the Error function // is shorter and less repetitive. -func NamedError(key string, err error) zapcore.Field { +func NamedError(key string, err error) Field { if err == nil { return Skip() } - return zapcore.Field{Key: key, Type: zapcore.ErrorType, Interface: err} + return Field{Key: key, Type: zapcore.ErrorType, Interface: err} } type errArray []error diff --git a/vendor/go.uber.org/zap/field.go b/vendor/go.uber.org/zap/field.go index 20eb487e142..5130e134771 100644 --- a/vendor/go.uber.org/zap/field.go +++ b/vendor/go.uber.org/zap/field.go @@ -28,10 +28,14 @@ import ( "go.uber.org/zap/zapcore" ) +// Field is an alias for Field. Aliasing this type dramatically +// improves the navigability of this package's API documentation. +type Field = zapcore.Field + // Skip constructs a no-op field, which is often useful when handling invalid // inputs in other Field constructors. -func Skip() zapcore.Field { - return zapcore.Field{Type: zapcore.SkipType} +func Skip() Field { + return Field{Type: zapcore.SkipType} } // Binary constructs a field that carries an opaque binary blob. @@ -39,112 +43,112 @@ func Skip() zapcore.Field { // Binary data is serialized in an encoding-appropriate format. For example, // zap's JSON encoder base64-encodes binary blobs. To log UTF-8 encoded text, // use ByteString. -func Binary(key string, val []byte) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.BinaryType, Interface: val} +func Binary(key string, val []byte) Field { + return Field{Key: key, Type: zapcore.BinaryType, Interface: val} } // Bool constructs a field that carries a bool. -func Bool(key string, val bool) zapcore.Field { +func Bool(key string, val bool) Field { var ival int64 if val { ival = 1 } - return zapcore.Field{Key: key, Type: zapcore.BoolType, Integer: ival} + return Field{Key: key, Type: zapcore.BoolType, Integer: ival} } // ByteString constructs a field that carries UTF-8 encoded text as a []byte. // To log opaque binary blobs (which aren't necessarily valid UTF-8), use // Binary. -func ByteString(key string, val []byte) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.ByteStringType, Interface: val} +func ByteString(key string, val []byte) Field { + return Field{Key: key, Type: zapcore.ByteStringType, Interface: val} } // Complex128 constructs a field that carries a complex number. Unlike most // numeric fields, this costs an allocation (to convert the complex128 to // interface{}). -func Complex128(key string, val complex128) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Complex128Type, Interface: val} +func Complex128(key string, val complex128) Field { + return Field{Key: key, Type: zapcore.Complex128Type, Interface: val} } // Complex64 constructs a field that carries a complex number. Unlike most // numeric fields, this costs an allocation (to convert the complex64 to // interface{}). -func Complex64(key string, val complex64) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Complex64Type, Interface: val} +func Complex64(key string, val complex64) Field { + return Field{Key: key, Type: zapcore.Complex64Type, Interface: val} } // Float64 constructs a field that carries a float64. The way the // floating-point value is represented is encoder-dependent, so marshaling is // necessarily lazy. -func Float64(key string, val float64) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Float64Type, Integer: int64(math.Float64bits(val))} +func Float64(key string, val float64) Field { + return Field{Key: key, Type: zapcore.Float64Type, Integer: int64(math.Float64bits(val))} } // Float32 constructs a field that carries a float32. The way the // floating-point value is represented is encoder-dependent, so marshaling is // necessarily lazy. -func Float32(key string, val float32) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Float32Type, Integer: int64(math.Float32bits(val))} +func Float32(key string, val float32) Field { + return Field{Key: key, Type: zapcore.Float32Type, Integer: int64(math.Float32bits(val))} } // Int constructs a field with the given key and value. -func Int(key string, val int) zapcore.Field { +func Int(key string, val int) Field { return Int64(key, int64(val)) } // Int64 constructs a field with the given key and value. -func Int64(key string, val int64) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Int64Type, Integer: val} +func Int64(key string, val int64) Field { + return Field{Key: key, Type: zapcore.Int64Type, Integer: val} } // Int32 constructs a field with the given key and value. -func Int32(key string, val int32) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Int32Type, Integer: int64(val)} +func Int32(key string, val int32) Field { + return Field{Key: key, Type: zapcore.Int32Type, Integer: int64(val)} } // Int16 constructs a field with the given key and value. -func Int16(key string, val int16) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Int16Type, Integer: int64(val)} +func Int16(key string, val int16) Field { + return Field{Key: key, Type: zapcore.Int16Type, Integer: int64(val)} } // Int8 constructs a field with the given key and value. -func Int8(key string, val int8) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Int8Type, Integer: int64(val)} +func Int8(key string, val int8) Field { + return Field{Key: key, Type: zapcore.Int8Type, Integer: int64(val)} } // String constructs a field with the given key and value. -func String(key string, val string) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.StringType, String: val} +func String(key string, val string) Field { + return Field{Key: key, Type: zapcore.StringType, String: val} } // Uint constructs a field with the given key and value. -func Uint(key string, val uint) zapcore.Field { +func Uint(key string, val uint) Field { return Uint64(key, uint64(val)) } // Uint64 constructs a field with the given key and value. -func Uint64(key string, val uint64) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Uint64Type, Integer: int64(val)} +func Uint64(key string, val uint64) Field { + return Field{Key: key, Type: zapcore.Uint64Type, Integer: int64(val)} } // Uint32 constructs a field with the given key and value. -func Uint32(key string, val uint32) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Uint32Type, Integer: int64(val)} +func Uint32(key string, val uint32) Field { + return Field{Key: key, Type: zapcore.Uint32Type, Integer: int64(val)} } // Uint16 constructs a field with the given key and value. -func Uint16(key string, val uint16) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Uint16Type, Integer: int64(val)} +func Uint16(key string, val uint16) Field { + return Field{Key: key, Type: zapcore.Uint16Type, Integer: int64(val)} } // Uint8 constructs a field with the given key and value. -func Uint8(key string, val uint8) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.Uint8Type, Integer: int64(val)} +func Uint8(key string, val uint8) Field { + return Field{Key: key, Type: zapcore.Uint8Type, Integer: int64(val)} } // Uintptr constructs a field with the given key and value. -func Uintptr(key string, val uintptr) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.UintptrType, Integer: int64(val)} +func Uintptr(key string, val uintptr) Field { + return Field{Key: key, Type: zapcore.UintptrType, Integer: int64(val)} } // Reflect constructs a field with the given key and an arbitrary object. It uses @@ -154,8 +158,8 @@ func Uintptr(key string, val uintptr) zapcore.Field { // // If encoding fails (e.g., trying to serialize a map[int]string to JSON), Reflect // includes the error message in the final log output. -func Reflect(key string, val interface{}) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.ReflectType, Interface: val} +func Reflect(key string, val interface{}) Field { + return Field{Key: key, Type: zapcore.ReflectType, Interface: val} } // Namespace creates a named, isolated scope within the logger's context. All @@ -163,27 +167,27 @@ func Reflect(key string, val interface{}) zapcore.Field { // // This helps prevent key collisions when injecting loggers into sub-components // or third-party libraries. -func Namespace(key string) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.NamespaceType} +func Namespace(key string) Field { + return Field{Key: key, Type: zapcore.NamespaceType} } // Stringer constructs a field with the given key and the output of the value's // String method. The Stringer's String method is called lazily. -func Stringer(key string, val fmt.Stringer) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.StringerType, Interface: val} +func Stringer(key string, val fmt.Stringer) Field { + return Field{Key: key, Type: zapcore.StringerType, Interface: val} } -// Time constructs a zapcore.Field with the given key and value. The encoder +// Time constructs a Field with the given key and value. The encoder // controls how the time is serialized. -func Time(key string, val time.Time) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.TimeType, Integer: val.UnixNano(), Interface: val.Location()} +func Time(key string, val time.Time) Field { + return Field{Key: key, Type: zapcore.TimeType, Integer: val.UnixNano(), Interface: val.Location()} } // Stack constructs a field that stores a stacktrace of the current goroutine // under provided key. Keep in mind that taking a stacktrace is eager and // expensive (relatively speaking); this function both makes an allocation and // takes about two microseconds. -func Stack(key string) zapcore.Field { +func Stack(key string) Field { // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation @@ -193,16 +197,16 @@ func Stack(key string) zapcore.Field { // Duration constructs a field with the given key and value. The encoder // controls how the duration is serialized. -func Duration(key string, val time.Duration) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.DurationType, Integer: int64(val)} +func Duration(key string, val time.Duration) Field { + return Field{Key: key, Type: zapcore.DurationType, Integer: int64(val)} } // Object constructs a field with the given key and ObjectMarshaler. It // provides a flexible, but still type-safe and efficient, way to add map- or // struct-like user-defined types to the logging context. The struct's // MarshalLogObject method is called lazily. -func Object(key string, val zapcore.ObjectMarshaler) zapcore.Field { - return zapcore.Field{Key: key, Type: zapcore.ObjectMarshalerType, Interface: val} +func Object(key string, val zapcore.ObjectMarshaler) Field { + return Field{Key: key, Type: zapcore.ObjectMarshalerType, Interface: val} } // Any takes a key and an arbitrary value and chooses the best way to represent @@ -210,9 +214,9 @@ func Object(key string, val zapcore.ObjectMarshaler) zapcore.Field { // necessary. // // Since byte/uint8 and rune/int32 are aliases, Any can't differentiate between -// them. To minimize suprise, []byte values are treated as binary blobs, byte +// them. To minimize surprises, []byte values are treated as binary blobs, byte // values are treated as uint8, and runes are always treated as integers. -func Any(key string, value interface{}) zapcore.Field { +func Any(key string, value interface{}) Field { switch val := value.(type) { case zapcore.ObjectMarshaler: return Object(key, val) diff --git a/vendor/go.uber.org/zap/global.go b/vendor/go.uber.org/zap/global.go index d3454550900..d02232e39fa 100644 --- a/vendor/go.uber.org/zap/global.go +++ b/vendor/go.uber.org/zap/global.go @@ -31,8 +31,10 @@ import ( ) const ( - _stdLogDefaultDepth = 2 - _loggerWriterDepth = 2 + _stdLogDefaultDepth = 2 + _loggerWriterDepth = 2 + _programmerErrorTemplate = "You've found a bug in zap! Please file a bug at " + + "https://github.com/uber-go/zap/issues/new and reference this error: %v" ) var ( @@ -83,24 +85,9 @@ func NewStdLog(l *Logger) *log.Logger { // required level. func NewStdLogAt(l *Logger, level zapcore.Level) (*log.Logger, error) { logger := l.WithOptions(AddCallerSkip(_stdLogDefaultDepth + _loggerWriterDepth)) - var logFunc func(string, ...zapcore.Field) - switch level { - case DebugLevel: - logFunc = logger.Debug - case InfoLevel: - logFunc = logger.Info - case WarnLevel: - logFunc = logger.Warn - case ErrorLevel: - logFunc = logger.Error - case DPanicLevel: - logFunc = logger.DPanic - case PanicLevel: - logFunc = logger.Panic - case FatalLevel: - logFunc = logger.Fatal - default: - return nil, fmt.Errorf("unrecognized level: %q", level) + logFunc, err := levelToFunc(logger, level) + if err != nil { + return nil, err } return log.New(&loggerWriter{logFunc}, "" /* prefix */, 0 /* flags */), nil } @@ -111,25 +98,68 @@ func NewStdLogAt(l *Logger, level zapcore.Level) (*log.Logger, error) { // library's annotations and prefixing. // // It returns a function to restore the original prefix and flags and reset the -// standard library's output to os.Stdout. +// standard library's output to os.Stderr. func RedirectStdLog(l *Logger) func() { + f, err := redirectStdLogAt(l, InfoLevel) + if err != nil { + // Can't get here, since passing InfoLevel to redirectStdLogAt always + // works. + panic(fmt.Sprintf(_programmerErrorTemplate, err)) + } + return f +} + +// RedirectStdLogAt redirects output from the standard library's package-global +// logger to the supplied logger at the specified level. Since zap already +// handles caller annotations, timestamps, etc., it automatically disables the +// standard library's annotations and prefixing. +// +// It returns a function to restore the original prefix and flags and reset the +// standard library's output to os.Stderr. +func RedirectStdLogAt(l *Logger, level zapcore.Level) (func(), error) { + return redirectStdLogAt(l, level) +} + +func redirectStdLogAt(l *Logger, level zapcore.Level) (func(), error) { flags := log.Flags() prefix := log.Prefix() log.SetFlags(0) log.SetPrefix("") - logFunc := l.WithOptions( - AddCallerSkip(_stdLogDefaultDepth + _loggerWriterDepth), - ).Info + logger := l.WithOptions(AddCallerSkip(_stdLogDefaultDepth + _loggerWriterDepth)) + logFunc, err := levelToFunc(logger, level) + if err != nil { + return nil, err + } log.SetOutput(&loggerWriter{logFunc}) return func() { log.SetFlags(flags) log.SetPrefix(prefix) log.SetOutput(os.Stderr) + }, nil +} + +func levelToFunc(logger *Logger, lvl zapcore.Level) (func(string, ...Field), error) { + switch lvl { + case DebugLevel: + return logger.Debug, nil + case InfoLevel: + return logger.Info, nil + case WarnLevel: + return logger.Warn, nil + case ErrorLevel: + return logger.Error, nil + case DPanicLevel: + return logger.DPanic, nil + case PanicLevel: + return logger.Panic, nil + case FatalLevel: + return logger.Fatal, nil } + return nil, fmt.Errorf("unrecognized level: %q", lvl) } type loggerWriter struct { - logFunc func(msg string, fields ...zapcore.Field) + logFunc func(msg string, fields ...Field) } func (l *loggerWriter) Write(p []byte) (int, error) { diff --git a/vendor/go.uber.org/zap/level.go b/vendor/go.uber.org/zap/level.go index 166101f378b..3567a9a1e6a 100644 --- a/vendor/go.uber.org/zap/level.go +++ b/vendor/go.uber.org/zap/level.go @@ -78,7 +78,7 @@ func NewAtomicLevel() AtomicLevel { } } -// NewAtomicLevelAt is a convienence function that creates an AtomicLevel +// NewAtomicLevelAt is a convenience function that creates an AtomicLevel // and then calls SetLevel with the given level. func NewAtomicLevelAt(l zapcore.Level) AtomicLevel { a := NewAtomicLevel() diff --git a/vendor/go.uber.org/zap/logger.go b/vendor/go.uber.org/zap/logger.go index 7d8824b486f..dc8f6e3a4bd 100644 --- a/vendor/go.uber.org/zap/logger.go +++ b/vendor/go.uber.org/zap/logger.go @@ -156,7 +156,7 @@ func (log *Logger) WithOptions(opts ...Option) *Logger { // With creates a child logger and adds structured context to it. Fields added // to the child don't affect the parent, and vice versa. -func (log *Logger) With(fields ...zapcore.Field) *Logger { +func (log *Logger) With(fields ...Field) *Logger { if len(fields) == 0 { return log } @@ -174,7 +174,7 @@ func (log *Logger) Check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry { // Debug logs a message at DebugLevel. The message includes any fields passed // at the log site, as well as any fields accumulated on the logger. -func (log *Logger) Debug(msg string, fields ...zapcore.Field) { +func (log *Logger) Debug(msg string, fields ...Field) { if ce := log.check(DebugLevel, msg); ce != nil { ce.Write(fields...) } @@ -182,7 +182,7 @@ func (log *Logger) Debug(msg string, fields ...zapcore.Field) { // Info logs a message at InfoLevel. The message includes any fields passed // at the log site, as well as any fields accumulated on the logger. -func (log *Logger) Info(msg string, fields ...zapcore.Field) { +func (log *Logger) Info(msg string, fields ...Field) { if ce := log.check(InfoLevel, msg); ce != nil { ce.Write(fields...) } @@ -190,7 +190,7 @@ func (log *Logger) Info(msg string, fields ...zapcore.Field) { // Warn logs a message at WarnLevel. The message includes any fields passed // at the log site, as well as any fields accumulated on the logger. -func (log *Logger) Warn(msg string, fields ...zapcore.Field) { +func (log *Logger) Warn(msg string, fields ...Field) { if ce := log.check(WarnLevel, msg); ce != nil { ce.Write(fields...) } @@ -198,7 +198,7 @@ func (log *Logger) Warn(msg string, fields ...zapcore.Field) { // Error logs a message at ErrorLevel. The message includes any fields passed // at the log site, as well as any fields accumulated on the logger. -func (log *Logger) Error(msg string, fields ...zapcore.Field) { +func (log *Logger) Error(msg string, fields ...Field) { if ce := log.check(ErrorLevel, msg); ce != nil { ce.Write(fields...) } @@ -210,7 +210,7 @@ func (log *Logger) Error(msg string, fields ...zapcore.Field) { // If the logger is in development mode, it then panics (DPanic means // "development panic"). This is useful for catching errors that are // recoverable, but shouldn't ever happen. -func (log *Logger) DPanic(msg string, fields ...zapcore.Field) { +func (log *Logger) DPanic(msg string, fields ...Field) { if ce := log.check(DPanicLevel, msg); ce != nil { ce.Write(fields...) } @@ -220,7 +220,7 @@ func (log *Logger) DPanic(msg string, fields ...zapcore.Field) { // at the log site, as well as any fields accumulated on the logger. // // The logger then panics, even if logging at PanicLevel is disabled. -func (log *Logger) Panic(msg string, fields ...zapcore.Field) { +func (log *Logger) Panic(msg string, fields ...Field) { if ce := log.check(PanicLevel, msg); ce != nil { ce.Write(fields...) } @@ -231,7 +231,7 @@ func (log *Logger) Panic(msg string, fields ...zapcore.Field) { // // The logger then calls os.Exit(1), even if logging at FatalLevel is // disabled. -func (log *Logger) Fatal(msg string, fields ...zapcore.Field) { +func (log *Logger) Fatal(msg string, fields ...Field) { if ce := log.check(FatalLevel, msg); ce != nil { ce.Write(fields...) } diff --git a/vendor/go.uber.org/zap/options.go b/vendor/go.uber.org/zap/options.go index d0f9422d055..7a6b0fca1b8 100644 --- a/vendor/go.uber.org/zap/options.go +++ b/vendor/go.uber.org/zap/options.go @@ -55,7 +55,7 @@ func Hooks(hooks ...func(zapcore.Entry) error) Option { } // Fields adds fields to the Logger. -func Fields(fs ...zapcore.Field) Option { +func Fields(fs ...Field) Option { return optionFunc(func(log *Logger) { log.core = log.core.With(fs) }) diff --git a/vendor/go.uber.org/zap/sugar.go b/vendor/go.uber.org/zap/sugar.go index 9cda00962c8..77ca227f47f 100644 --- a/vendor/go.uber.org/zap/sugar.go +++ b/vendor/go.uber.org/zap/sugar.go @@ -62,9 +62,9 @@ func (s *SugaredLogger) Named(name string) *SugaredLogger { } // With adds a variadic number of fields to the logging context. It accepts a -// mix of strongly-typed zapcore.Field objects and loosely-typed key-value -// pairs. When processing pairs, the first element of the pair is used as the -// field key and the second as the field value. +// mix of strongly-typed Field objects and loosely-typed key-value pairs. When +// processing pairs, the first element of the pair is used as the field key +// and the second as the field value. // // For example, // sugaredLogger.With( @@ -235,19 +235,19 @@ func (s *SugaredLogger) log(lvl zapcore.Level, template string, fmtArgs []interf } } -func (s *SugaredLogger) sweetenFields(args []interface{}) []zapcore.Field { +func (s *SugaredLogger) sweetenFields(args []interface{}) []Field { if len(args) == 0 { return nil } // Allocate enough space for the worst case; if users pass only structured // fields, we shouldn't penalize them with extra allocations. - fields := make([]zapcore.Field, 0, len(args)) + fields := make([]Field, 0, len(args)) var invalid invalidPairs for i := 0; i < len(args); { // This is a strongly-typed field. Consume it and move on. - if f, ok := args[i].(zapcore.Field); ok { + if f, ok := args[i].(Field); ok { fields = append(fields, f) i++ continue From 5828efda38e0fae6ed8ac6cb38467149f3262ad1 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 13:26:39 -0700 Subject: [PATCH 15/16] *: use "zap.Field" Signed-off-by: Gyuho Lee --- embed/etcd.go | 4 +--- etcdserver/corrupt.go | 3 +-- etcdserver/server.go | 3 +-- 3 files changed, 3 insertions(+), 7 deletions(-) diff --git a/embed/etcd.go b/embed/etcd.go index 1206a8882f8..397516ea030 100644 --- a/embed/etcd.go +++ b/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()), diff --git a/etcdserver/corrupt.go b/etcdserver/corrupt.go index 5c88d355dda..d4cd9f2e67d 100644 --- a/etcdserver/corrupt.go +++ b/etcdserver/corrupt.go @@ -26,7 +26,6 @@ import ( "github.com/coreos/etcd/pkg/types" "go.uber.org/zap" - "go.uber.org/zap/zapcore" ) // CheckInitialHashKV compares initial hash values with its peers @@ -58,7 +57,7 @@ func (s *EtcdServer) CheckInitialHashKV() error { for _, p := range peers { if p.resp != nil { peerID := types.ID(p.resp.Header.MemberId) - fields := []zapcore.Field{ + fields := []zap.Field{ zap.String("local-member-id", s.ID().String()), zap.Int64("local-member-revision", rev), zap.Int64("local-member-compact-revision", crev), diff --git a/etcdserver/server.go b/etcdserver/server.go index 0bf9f00f752..eb2ce861690 100644 --- a/etcdserver/server.go +++ b/etcdserver/server.go @@ -61,7 +61,6 @@ import ( "github.com/coreos/go-semver/semver" "github.com/coreos/pkg/capnslog" "go.uber.org/zap" - "go.uber.org/zap/zapcore" ) const ( @@ -1816,7 +1815,7 @@ func (s *EtcdServer) sendMergedSnap(merged raftsnap.Message) { atomic.AddInt64(&s.inflightSnapshots, 1) lg := s.getLogger() - fields := []zapcore.Field{ + fields := []zap.Field{ zap.String("from", s.ID().String()), zap.String("to", types.ID(merged.To).String()), zap.Int64("bytes", merged.TotalSize), From 617e0aaafb75dd7644db3f87b18d1b1e1e97fbf9 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 13:28:22 -0700 Subject: [PATCH 16/16] CHANGELOG-3.4: move "Tooling" above Signed-off-by: Gyuho Lee --- CHANGELOG-3.4.md | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/CHANGELOG-3.4.md b/CHANGELOG-3.4.md index dc6d3881419..c27bc5b915f 100644 --- a/CHANGELOG-3.4.md +++ b/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. -