From cccf77db9e5cf1ef01015826e1317e5e4cd4385d Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Wed, 2 May 2018 11:34:21 -0700 Subject: [PATCH] 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 c69a9316b..e94768660 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 17f0fe6d5..5316d5bf4 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 195973fb1..93fc5a409 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 10ee25882..78fcdcbf4 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 8719a2d39..fc1f5894a 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 679254577..30e1945f7 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) }