etcdserver/v2auth: support structured logging

Signed-off-by: Gyuho Lee <gyuhox@gmail.com>

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,8 +211,12 @@ func (s *store) CreateUser(user User) (User, error) {
 	}
 	u, err := s.createUserInternal(user)
 	if err == nil {
+		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
 	}
+	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,8 +282,12 @@ func (s *store) UpdateUser(user User) (User, error) {
 	}
 	_, err = s.updateResource("/users/"+user.User, newUser)
 	if err == nil {
+		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,8 +325,12 @@ func (s *store) CreateRole(role Role) error {
 		}
 	}
 	if err == nil {
+		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,8 +347,12 @@ func (s *store) DeleteRole(name string) error {
 		}
 	}
 	if err == nil {
+		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,8 +378,12 @@ func (s *store) UpdateRole(role Role) (Role, error) {
 	}
 	_, err = s.updateResource("/roles/"+role.Role, newRole)
 	if err == nil {
+		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 {
+		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 {
+			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 {
+		if s.lg != nil {
+			s.lg.Warn("failed to enable auth", zap.Error(err))
+		} else {
 			plog.Errorf("error enabling auth (%v)", err)
+		}
 		return err
 	}
 
+	if s.lg != nil {
+		s.lg.Info("enabled auth")
+	} else {
 		plog.Noticef("auth: enabled auth")
+	}
 	return nil
 }
 
@@ -396,10 +446,18 @@ func (s *store) DisableAuth() error {
 
 	err := s.disableAuth()
 	if err == nil {
+		if s.lg != nil {
+			s.lg.Info("disabled auth")
+		} else {
 			plog.Noticef("auth: disabled auth")
+		}
+	} else {
+		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) {
+			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) {
+			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) {
+			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) {
+			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)

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
 				}
 			}
+			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
 			}
 		}
+		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 {
+		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

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")