Browse Source

auth: support structured logging

Signed-off-by: Gyuho Lee <gyuhox@gmail.com>
Gyuho Lee 7 years ago
parent
commit
da4a982b1c
8 changed files with 454 additions and 127 deletions
  1. 90 14
      auth/jwt.go
  2. 8 6
      auth/jwt_test.go
  3. 31 11
      auth/range_perm_cache.go
  4. 3 1
      auth/range_perm_cache_test.go
  5. 23 3
      auth/simple_token.go
  6. 5 3
      auth/simple_token_test.go
  7. 287 82
      auth/store.go
  8. 7 7
      auth/store_test.go

+ 90 - 14
auth/jwt.go

@@ -21,9 +21,11 @@ import (
 	"time"
 
 	jwt "github.com/dgrijalva/jwt-go"
+	"go.uber.org/zap"
 )
 
 type tokenJWT struct {
+	lg         *zap.Logger
 	signMethod string
 	signKey    *rsa.PrivateKey
 	verifyKey  *rsa.PublicKey
@@ -49,7 +51,11 @@ func (t *tokenJWT) info(ctx context.Context, token string, rev uint64) (*AuthInf
 	switch err.(type) {
 	case nil:
 		if !parsed.Valid {
-			plog.Warningf("invalid jwt token: %s", token)
+			if t.lg != nil {
+				t.lg.Warn("invalid JWT token", zap.String("token", token))
+			} else {
+				plog.Warningf("invalid jwt token: %s", token)
+			}
 			return nil, false
 		}
 
@@ -58,7 +64,15 @@ func (t *tokenJWT) info(ctx context.Context, token string, rev uint64) (*AuthInf
 		username = claims["username"].(string)
 		revision = uint64(claims["revision"].(float64))
 	default:
-		plog.Warningf("failed to parse jwt token: %s", err)
+		if t.lg != nil {
+			t.lg.Warn(
+				"failed to parse a JWT token",
+				zap.String("token", token),
+				zap.Error(err),
+			)
+		} else {
+			plog.Warningf("failed to parse jwt token: %s", err)
+		}
 		return nil, false
 	}
 
@@ -77,16 +91,33 @@ func (t *tokenJWT) assign(ctx context.Context, username string, revision uint64)
 
 	token, err := tk.SignedString(t.signKey)
 	if err != nil {
-		plog.Debugf("failed to sign jwt token: %s", err)
+		if t.lg != nil {
+			t.lg.Warn(
+				"failed to sign a JWT token",
+				zap.String("user-name", username),
+				zap.Uint64("revision", revision),
+				zap.Error(err),
+			)
+		} else {
+			plog.Debugf("failed to sign jwt token: %s", err)
+		}
 		return "", err
 	}
 
-	plog.Debugf("jwt token: %s", token)
-
+	if t.lg != nil {
+		t.lg.Info(
+			"created/assigned a new JWT token",
+			zap.String("user-name", username),
+			zap.Uint64("revision", revision),
+			zap.String("token", token),
+		)
+	} else {
+		plog.Debugf("jwt token: %s", token)
+	}
 	return token, err
 }
 
-func prepareOpts(opts map[string]string) (jwtSignMethod, jwtPubKeyPath, jwtPrivKeyPath string, ttl time.Duration, err error) {
+func prepareOpts(lg *zap.Logger, opts map[string]string) (jwtSignMethod, jwtPubKeyPath, jwtPrivKeyPath string, ttl time.Duration, err error) {
 	for k, v := range opts {
 		switch k {
 		case "sign-method":
@@ -98,11 +129,23 @@ func prepareOpts(opts map[string]string) (jwtSignMethod, jwtPubKeyPath, jwtPrivK
 		case "ttl":
 			ttl, err = time.ParseDuration(v)
 			if err != nil {
-				plog.Errorf("failed to parse ttl option (%s)", err)
+				if lg != nil {
+					lg.Warn(
+						"failed to parse JWT TTL option",
+						zap.String("ttl-value", v),
+						zap.Error(err),
+					)
+				} else {
+					plog.Errorf("failed to parse ttl option (%s)", err)
+				}
 				return "", "", "", 0, ErrInvalidAuthOpts
 			}
 		default:
-			plog.Errorf("unknown token specific option: %s", k)
+			if lg != nil {
+				lg.Warn("unknown JWT token option", zap.String("option", k))
+			} else {
+				plog.Errorf("unknown token specific option: %s", k)
+			}
 			return "", "", "", 0, ErrInvalidAuthOpts
 		}
 	}
@@ -112,8 +155,8 @@ func prepareOpts(opts map[string]string) (jwtSignMethod, jwtPubKeyPath, jwtPrivK
 	return jwtSignMethod, jwtPubKeyPath, jwtPrivKeyPath, ttl, nil
 }
 
-func newTokenProviderJWT(opts map[string]string) (*tokenJWT, error) {
-	jwtSignMethod, jwtPubKeyPath, jwtPrivKeyPath, ttl, err := prepareOpts(opts)
+func newTokenProviderJWT(lg *zap.Logger, opts map[string]string) (*tokenJWT, error) {
+	jwtSignMethod, jwtPubKeyPath, jwtPrivKeyPath, ttl, err := prepareOpts(lg, opts)
 	if err != nil {
 		return nil, ErrInvalidAuthOpts
 	}
@@ -123,6 +166,7 @@ func newTokenProviderJWT(opts map[string]string) (*tokenJWT, error) {
 	}
 
 	t := &tokenJWT{
+		lg:  lg,
 		ttl: ttl,
 	}
 
@@ -130,23 +174,55 @@ func newTokenProviderJWT(opts map[string]string) (*tokenJWT, error) {
 
 	verifyBytes, err := ioutil.ReadFile(jwtPubKeyPath)
 	if err != nil {
-		plog.Errorf("failed to read public key (%s) for jwt: %s", jwtPubKeyPath, err)
+		if lg != nil {
+			lg.Warn(
+				"failed to read JWT public key",
+				zap.String("public-key-path", jwtPubKeyPath),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to read public key (%s) for jwt: %s", jwtPubKeyPath, err)
+		}
 		return nil, err
 	}
 	t.verifyKey, err = jwt.ParseRSAPublicKeyFromPEM(verifyBytes)
 	if err != nil {
-		plog.Errorf("failed to parse public key (%s): %s", jwtPubKeyPath, err)
+		if lg != nil {
+			lg.Warn(
+				"failed to parse JWT public key",
+				zap.String("public-key-path", jwtPubKeyPath),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to parse public key (%s): %s", jwtPubKeyPath, err)
+		}
 		return nil, err
 	}
 
 	signBytes, err := ioutil.ReadFile(jwtPrivKeyPath)
 	if err != nil {
-		plog.Errorf("failed to read private key (%s) for jwt: %s", jwtPrivKeyPath, err)
+		if lg != nil {
+			lg.Warn(
+				"failed to read JWT private key",
+				zap.String("private-key-path", jwtPrivKeyPath),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to read private key (%s) for jwt: %s", jwtPrivKeyPath, err)
+		}
 		return nil, err
 	}
 	t.signKey, err = jwt.ParseRSAPrivateKeyFromPEM(signBytes)
 	if err != nil {
-		plog.Errorf("failed to parse private key (%s): %s", jwtPrivKeyPath, err)
+		if lg != nil {
+			lg.Warn(
+				"failed to parse JWT private key",
+				zap.String("private-key-path", jwtPrivKeyPath),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to parse private key (%s): %s", jwtPrivKeyPath, err)
+		}
 		return nil, err
 	}
 

+ 8 - 6
auth/jwt_test.go

@@ -17,6 +17,8 @@ package auth
 import (
 	"context"
 	"testing"
+
+	"go.uber.org/zap"
 )
 
 const (
@@ -30,7 +32,7 @@ func TestJWTInfo(t *testing.T) {
 		"priv-key":    jwtPrivKey,
 		"sign-method": "RS256",
 	}
-	jwt, err := newTokenProviderJWT(opts)
+	jwt, err := newTokenProviderJWT(zap.NewExample(), opts)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -59,35 +61,35 @@ func TestJWTBad(t *testing.T) {
 	}
 	// private key instead of public key
 	opts["pub-key"] = jwtPrivKey
-	if _, err := newTokenProviderJWT(opts); err == nil {
+	if _, err := newTokenProviderJWT(zap.NewExample(), opts); err == nil {
 		t.Fatalf("expected failure on missing public key")
 	}
 	opts["pub-key"] = jwtPubKey
 
 	// public key instead of private key
 	opts["priv-key"] = jwtPubKey
-	if _, err := newTokenProviderJWT(opts); err == nil {
+	if _, err := newTokenProviderJWT(zap.NewExample(), opts); err == nil {
 		t.Fatalf("expected failure on missing public key")
 	}
 	opts["priv-key"] = jwtPrivKey
 
 	// missing signing option
 	delete(opts, "sign-method")
-	if _, err := newTokenProviderJWT(opts); err == nil {
+	if _, err := newTokenProviderJWT(zap.NewExample(), opts); err == nil {
 		t.Fatal("expected error on missing option")
 	}
 	opts["sign-method"] = "RS256"
 
 	// bad file for pubkey
 	opts["pub-key"] = "whatever"
-	if _, err := newTokenProviderJWT(opts); err == nil {
+	if _, err := newTokenProviderJWT(zap.NewExample(), opts); err == nil {
 		t.Fatalf("expected failure on missing public key")
 	}
 	opts["pub-key"] = jwtPubKey
 
 	// bad file for private key
 	opts["priv-key"] = "whatever"
-	if _, err := newTokenProviderJWT(opts); err == nil {
+	if _, err := newTokenProviderJWT(zap.NewExample(), opts); err == nil {
 		t.Fatalf("expeceted failure on missing private key")
 	}
 	opts["priv-key"] = jwtPrivKey

+ 31 - 11
auth/range_perm_cache.go

@@ -18,12 +18,13 @@ import (
 	"github.com/coreos/etcd/auth/authpb"
 	"github.com/coreos/etcd/mvcc/backend"
 	"github.com/coreos/etcd/pkg/adt"
+
+	"go.uber.org/zap"
 )
 
-func getMergedPerms(tx backend.BatchTx, userName string) *unifiedRangePermissions {
-	user := getUser(tx, userName)
+func getMergedPerms(lg *zap.Logger, tx backend.BatchTx, userName string) *unifiedRangePermissions {
+	user := getUser(lg, tx, userName)
 	if user == nil {
-		plog.Errorf("invalid user name %s", userName)
 		return nil
 	}
 
@@ -70,7 +71,11 @@ func getMergedPerms(tx backend.BatchTx, userName string) *unifiedRangePermission
 	}
 }
 
-func checkKeyInterval(cachedPerms *unifiedRangePermissions, key, rangeEnd []byte, permtyp authpb.Permission_Type) bool {
+func checkKeyInterval(
+	lg *zap.Logger,
+	cachedPerms *unifiedRangePermissions,
+	key, rangeEnd []byte,
+	permtyp authpb.Permission_Type) bool {
 	if len(rangeEnd) == 1 && rangeEnd[0] == 0 {
 		rangeEnd = nil
 	}
@@ -82,12 +87,16 @@ func checkKeyInterval(cachedPerms *unifiedRangePermissions, key, rangeEnd []byte
 	case authpb.WRITE:
 		return cachedPerms.writePerms.Contains(ivl)
 	default:
-		plog.Panicf("unknown auth type: %v", permtyp)
+		if lg != nil {
+			lg.Panic("unknown auth type", zap.String("auth-type", permtyp.String()))
+		} else {
+			plog.Panicf("unknown auth type: %v", permtyp)
+		}
 	}
 	return false
 }
 
-func checkKeyPoint(cachedPerms *unifiedRangePermissions, key []byte, permtyp authpb.Permission_Type) bool {
+func checkKeyPoint(lg *zap.Logger, cachedPerms *unifiedRangePermissions, key []byte, permtyp authpb.Permission_Type) bool {
 	pt := adt.NewBytesAffinePoint(key)
 	switch permtyp {
 	case authpb.READ:
@@ -95,7 +104,11 @@ func checkKeyPoint(cachedPerms *unifiedRangePermissions, key []byte, permtyp aut
 	case authpb.WRITE:
 		return cachedPerms.writePerms.Intersects(pt)
 	default:
-		plog.Panicf("unknown auth type: %v", permtyp)
+		if lg != nil {
+			lg.Panic("unknown auth type", zap.String("auth-type", permtyp.String()))
+		} else {
+			plog.Panicf("unknown auth type: %v", permtyp)
+		}
 	}
 	return false
 }
@@ -104,19 +117,26 @@ func (as *authStore) isRangeOpPermitted(tx backend.BatchTx, userName string, key
 	// assumption: tx is Lock()ed
 	_, ok := as.rangePermCache[userName]
 	if !ok {
-		perms := getMergedPerms(tx, userName)
+		perms := getMergedPerms(as.lg, tx, userName)
 		if perms == nil {
-			plog.Errorf("failed to create a unified permission of user %s", userName)
+			if as.lg != nil {
+				as.lg.Warn(
+					"failed to create a merged permission",
+					zap.String("user-name", userName),
+				)
+			} else {
+				plog.Errorf("failed to create a unified permission of user %s", userName)
+			}
 			return false
 		}
 		as.rangePermCache[userName] = perms
 	}
 
 	if len(rangeEnd) == 0 {
-		return checkKeyPoint(as.rangePermCache[userName], key, permtyp)
+		return checkKeyPoint(as.lg, as.rangePermCache[userName], key, permtyp)
 	}
 
-	return checkKeyInterval(as.rangePermCache[userName], key, rangeEnd, permtyp)
+	return checkKeyInterval(as.lg, as.rangePermCache[userName], key, rangeEnd, permtyp)
 }
 
 func (as *authStore) clearCachedPerm() {

+ 3 - 1
auth/range_perm_cache_test.go

@@ -19,6 +19,8 @@ import (
 
 	"github.com/coreos/etcd/auth/authpb"
 	"github.com/coreos/etcd/pkg/adt"
+
+	"go.uber.org/zap"
 )
 
 func TestRangePermission(t *testing.T) {
@@ -51,7 +53,7 @@ func TestRangePermission(t *testing.T) {
 			readPerms.Insert(p, struct{}{})
 		}
 
-		result := checkKeyInterval(&unifiedRangePermissions{readPerms: readPerms}, tt.begin, tt.end, authpb.READ)
+		result := checkKeyInterval(zap.NewExample(), &unifiedRangePermissions{readPerms: readPerms}, tt.begin, tt.end, authpb.READ)
 		if result != tt.want {
 			t.Errorf("#%d: result=%t, want=%t", i, result, tt.want)
 		}

+ 23 - 3
auth/simple_token.go

@@ -26,6 +26,8 @@ import (
 	"strings"
 	"sync"
 	"time"
+
+	"go.uber.org/zap"
 )
 
 const (
@@ -94,6 +96,7 @@ func (tm *simpleTokenTTLKeeper) run() {
 }
 
 type tokenSimple struct {
+	lg                *zap.Logger
 	indexWaiter       func(uint64) <-chan struct{}
 	simpleTokenKeeper *simpleTokenTTLKeeper
 	simpleTokensMu    sync.Mutex
@@ -124,7 +127,15 @@ func (t *tokenSimple) assignSimpleTokenToUser(username, token string) {
 
 	_, ok := t.simpleTokens[token]
 	if ok {
-		plog.Panicf("token %s is alredy used", token)
+		if t.lg != nil {
+			t.lg.Panic(
+				"failed to assign already-used simple token to a user",
+				zap.String("user-name", username),
+				zap.String("token", token),
+			)
+		} else {
+			plog.Panicf("token %s is alredy used", token)
+		}
 	}
 
 	t.simpleTokens[token] = username
@@ -148,7 +159,15 @@ func (t *tokenSimple) invalidateUser(username string) {
 func (t *tokenSimple) enable() {
 	delf := func(tk string) {
 		if username, ok := t.simpleTokens[tk]; ok {
-			plog.Infof("deleting token %s for user %s", tk, username)
+			if t.lg != nil {
+				t.lg.Info(
+					"deleted a simple token",
+					zap.String("user-name", username),
+					zap.String("token", tk),
+				)
+			} else {
+				plog.Infof("deleting token %s for user %s", tk, username)
+			}
 			delete(t.simpleTokens, tk)
 		}
 	}
@@ -215,8 +234,9 @@ func (t *tokenSimple) isValidSimpleToken(ctx context.Context, token string) bool
 	return false
 }
 
-func newTokenProviderSimple(indexWaiter func(uint64) <-chan struct{}) *tokenSimple {
+func newTokenProviderSimple(lg *zap.Logger, indexWaiter func(uint64) <-chan struct{}) *tokenSimple {
 	return &tokenSimple{
+		lg:           lg,
 		simpleTokens: make(map[string]string),
 		indexWaiter:  indexWaiter,
 	}

+ 5 - 3
auth/simple_token_test.go

@@ -17,14 +17,16 @@ package auth
 import (
 	"context"
 	"testing"
+
+	"go.uber.org/zap"
 )
 
 // TestSimpleTokenDisabled ensures that TokenProviderSimple behaves correctly when
 // disabled.
 func TestSimpleTokenDisabled(t *testing.T) {
-	initialState := newTokenProviderSimple(dummyIndexWaiter)
+	initialState := newTokenProviderSimple(zap.NewExample(), dummyIndexWaiter)
 
-	explicitlyDisabled := newTokenProviderSimple(dummyIndexWaiter)
+	explicitlyDisabled := newTokenProviderSimple(zap.NewExample(), dummyIndexWaiter)
 	explicitlyDisabled.enable()
 	explicitlyDisabled.disable()
 
@@ -46,7 +48,7 @@ func TestSimpleTokenDisabled(t *testing.T) {
 // TestSimpleTokenAssign ensures that TokenProviderSimple can correctly assign a
 // token, look it up with info, and invalidate it by user.
 func TestSimpleTokenAssign(t *testing.T) {
-	tp := newTokenProviderSimple(dummyIndexWaiter)
+	tp := newTokenProviderSimple(zap.NewExample(), dummyIndexWaiter)
 	tp.enable()
 	ctx := context.WithValue(context.WithValue(context.TODO(), AuthenticateParamIndex{}, uint64(1)), AuthenticateParamSimpleTokenPrefix{}, "dummy")
 	token, err := tp.assign(ctx, "user1", 0)

+ 287 - 82
auth/store.go

@@ -89,6 +89,7 @@ type AuthenticateParamIndex struct{}
 // AuthenticateParamSimpleTokenPrefix is used for a key of context in the parameters of Authenticate()
 type AuthenticateParamSimpleTokenPrefix struct{}
 
+// AuthStore defines auth storage interface.
 type AuthStore interface {
 	// AuthEnable turns on the authentication feature
 	AuthEnable() error
@@ -196,6 +197,7 @@ type authStore struct {
 	// atomic operations; need 64-bit align, or 32-bit tests will crash
 	revision uint64
 
+	lg        *zap.Logger
 	be        backend.Backend
 	enabled   bool
 	enabledMu sync.RWMutex
@@ -209,7 +211,11 @@ func (as *authStore) AuthEnable() error {
 	as.enabledMu.Lock()
 	defer as.enabledMu.Unlock()
 	if as.enabled {
-		plog.Noticef("Authentication already enabled")
+		if as.lg != nil {
+			as.lg.Info("authentication is already enabled; ignored auth enable request")
+		} else {
+			plog.Noticef("Authentication already enabled")
+		}
 		return nil
 	}
 	b := as.be
@@ -220,7 +226,7 @@ func (as *authStore) AuthEnable() error {
 		b.ForceCommit()
 	}()
 
-	u := getUser(tx, rootUser)
+	u := getUser(as.lg, tx, rootUser)
 	if u == nil {
 		return ErrRootUserNotExist
 	}
@@ -238,8 +244,11 @@ func (as *authStore) AuthEnable() error {
 
 	as.setRevision(getRevision(tx))
 
-	plog.Noticef("Authentication enabled")
-
+	if as.lg != nil {
+		as.lg.Info("enabled authentication")
+	} else {
+		plog.Noticef("Authentication enabled")
+	}
 	return nil
 }
 
@@ -260,7 +269,11 @@ func (as *authStore) AuthDisable() {
 	as.enabled = false
 	as.tokenProvider.disable()
 
-	plog.Noticef("Authentication disabled")
+	if as.lg != nil {
+		as.lg.Info("disabled authentication")
+	} else {
+		plog.Noticef("Authentication disabled")
+	}
 }
 
 func (as *authStore) Close() error {
@@ -282,7 +295,7 @@ func (as *authStore) Authenticate(ctx context.Context, username, password string
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, username)
+	user := getUser(as.lg, tx, username)
 	if user == nil {
 		return nil, ErrAuthFailed
 	}
@@ -295,7 +308,15 @@ func (as *authStore) Authenticate(ctx context.Context, username, password string
 		return nil, err
 	}
 
-	plog.Debugf("authorized %s, token is %s", username, token)
+	if as.lg != nil {
+		as.lg.Debug(
+			"authenticated a user",
+			zap.String("user-name", username),
+			zap.String("token", token),
+		)
+	} else {
+		plog.Debugf("authorized %s, token is %s", username, token)
+	}
 	return &pb.AuthenticateResponse{Token: token}, nil
 }
 
@@ -308,16 +329,19 @@ func (as *authStore) CheckPassword(username, password string) (uint64, error) {
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, username)
+	user := getUser(as.lg, tx, username)
 	if user == nil {
 		return 0, ErrAuthFailed
 	}
 
 	if bcrypt.CompareHashAndPassword(user.Password, []byte(password)) != nil {
-		plog.Noticef("authentication failed, invalid password for user %s", username)
+		if as.lg != nil {
+			as.lg.Info("invalid password", zap.String("user-name", username))
+		} else {
+			plog.Noticef("authentication failed, invalid password for user %s", username)
+		}
 		return 0, ErrAuthFailed
 	}
-
 	return getRevision(tx), nil
 }
 
@@ -349,7 +373,15 @@ func (as *authStore) UserAdd(r *pb.AuthUserAddRequest) (*pb.AuthUserAddResponse,
 
 	hashed, err := bcrypt.GenerateFromPassword([]byte(r.Password), BcryptCost)
 	if err != nil {
-		plog.Errorf("failed to hash password: %s", err)
+		if as.lg != nil {
+			as.lg.Warn(
+				"failed to bcrypt hash password",
+				zap.String("user-name", r.Name),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to hash password: %s", err)
+		}
 		return nil, err
 	}
 
@@ -357,7 +389,7 @@ func (as *authStore) UserAdd(r *pb.AuthUserAddRequest) (*pb.AuthUserAddResponse,
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, r.Name)
+	user := getUser(as.lg, tx, r.Name)
 	if user != nil {
 		return nil, ErrUserAlreadyExist
 	}
@@ -367,18 +399,25 @@ func (as *authStore) UserAdd(r *pb.AuthUserAddRequest) (*pb.AuthUserAddResponse,
 		Password: hashed,
 	}
 
-	putUser(tx, newUser)
+	putUser(as.lg, tx, newUser)
 
 	as.commitRevision(tx)
 
-	plog.Noticef("added a new user: %s", r.Name)
-
+	if as.lg != nil {
+		as.lg.Info("added a user", zap.String("user-name", r.Name))
+	} else {
+		plog.Noticef("added a new user: %s", r.Name)
+	}
 	return &pb.AuthUserAddResponse{}, nil
 }
 
 func (as *authStore) UserDelete(r *pb.AuthUserDeleteRequest) (*pb.AuthUserDeleteResponse, error) {
 	if as.enabled && strings.Compare(r.Name, rootUser) == 0 {
-		plog.Errorf("the user root must not be deleted")
+		if as.lg != nil {
+			as.lg.Warn("cannot delete 'root' user", zap.String("user-name", r.Name))
+		} else {
+			plog.Errorf("the user root must not be deleted")
+		}
 		return nil, ErrInvalidAuthMgmt
 	}
 
@@ -386,7 +425,7 @@ func (as *authStore) UserDelete(r *pb.AuthUserDeleteRequest) (*pb.AuthUserDelete
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, r.Name)
+	user := getUser(as.lg, tx, r.Name)
 	if user == nil {
 		return nil, ErrUserNotFound
 	}
@@ -398,8 +437,15 @@ func (as *authStore) UserDelete(r *pb.AuthUserDeleteRequest) (*pb.AuthUserDelete
 	as.invalidateCachedPerm(r.Name)
 	as.tokenProvider.invalidateUser(r.Name)
 
-	plog.Noticef("deleted a user: %s", r.Name)
-
+	if as.lg != nil {
+		as.lg.Info(
+			"deleted a user",
+			zap.String("user-name", r.Name),
+			zap.Strings("user-roles", user.Roles),
+		)
+	} else {
+		plog.Noticef("deleted a user: %s", r.Name)
+	}
 	return &pb.AuthUserDeleteResponse{}, nil
 }
 
@@ -408,7 +454,15 @@ func (as *authStore) UserChangePassword(r *pb.AuthUserChangePasswordRequest) (*p
 	// If the cost is too high, we should move the encryption to outside of the raft
 	hashed, err := bcrypt.GenerateFromPassword([]byte(r.Password), BcryptCost)
 	if err != nil {
-		plog.Errorf("failed to hash password: %s", err)
+		if as.lg != nil {
+			as.lg.Warn(
+				"failed to bcrypt hash password",
+				zap.String("user-name", r.Name),
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to hash password: %s", err)
+		}
 		return nil, err
 	}
 
@@ -416,7 +470,7 @@ func (as *authStore) UserChangePassword(r *pb.AuthUserChangePasswordRequest) (*p
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, r.Name)
+	user := getUser(as.lg, tx, r.Name)
 	if user == nil {
 		return nil, ErrUserNotFound
 	}
@@ -427,15 +481,22 @@ func (as *authStore) UserChangePassword(r *pb.AuthUserChangePasswordRequest) (*p
 		Password: hashed,
 	}
 
-	putUser(tx, updatedUser)
+	putUser(as.lg, tx, updatedUser)
 
 	as.commitRevision(tx)
 
 	as.invalidateCachedPerm(r.Name)
 	as.tokenProvider.invalidateUser(r.Name)
 
-	plog.Noticef("changed a password of a user: %s", r.Name)
-
+	if as.lg != nil {
+		as.lg.Info(
+			"changed a password of a user",
+			zap.String("user-name", r.Name),
+			zap.Strings("user-roles", user.Roles),
+		)
+	} else {
+		plog.Noticef("changed a password of a user: %s", r.Name)
+	}
 	return &pb.AuthUserChangePasswordResponse{}, nil
 }
 
@@ -444,7 +505,7 @@ func (as *authStore) UserGrantRole(r *pb.AuthUserGrantRoleRequest) (*pb.AuthUser
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, r.User)
+	user := getUser(as.lg, tx, r.User)
 	if user == nil {
 		return nil, ErrUserNotFound
 	}
@@ -458,27 +519,45 @@ func (as *authStore) UserGrantRole(r *pb.AuthUserGrantRoleRequest) (*pb.AuthUser
 
 	idx := sort.SearchStrings(user.Roles, r.Role)
 	if idx < len(user.Roles) && strings.Compare(user.Roles[idx], r.Role) == 0 {
-		plog.Warningf("user %s is already granted role %s", r.User, r.Role)
+		if as.lg != nil {
+			as.lg.Warn(
+				"ignored grant role request to a user",
+				zap.String("user-name", r.User),
+				zap.Strings("user-roles", user.Roles),
+				zap.String("duplicate-role-name", r.Role),
+			)
+		} else {
+			plog.Warningf("user %s is already granted role %s", r.User, r.Role)
+		}
 		return &pb.AuthUserGrantRoleResponse{}, nil
 	}
 
 	user.Roles = append(user.Roles, r.Role)
 	sort.Strings(user.Roles)
 
-	putUser(tx, user)
+	putUser(as.lg, tx, user)
 
 	as.invalidateCachedPerm(r.User)
 
 	as.commitRevision(tx)
 
-	plog.Noticef("granted role %s to user %s", r.Role, r.User)
+	if as.lg != nil {
+		as.lg.Info(
+			"granted a role to a user",
+			zap.String("user-name", r.User),
+			zap.Strings("user-roles", user.Roles),
+			zap.String("added-role-name", r.Role),
+		)
+	} else {
+		plog.Noticef("granted role %s to user %s", r.Role, r.User)
+	}
 	return &pb.AuthUserGrantRoleResponse{}, nil
 }
 
 func (as *authStore) UserGet(r *pb.AuthUserGetRequest) (*pb.AuthUserGetResponse, error) {
 	tx := as.be.BatchTx()
 	tx.Lock()
-	user := getUser(tx, r.Name)
+	user := getUser(as.lg, tx, r.Name)
 	tx.Unlock()
 
 	if user == nil {
@@ -493,7 +572,7 @@ func (as *authStore) UserGet(r *pb.AuthUserGetRequest) (*pb.AuthUserGetResponse,
 func (as *authStore) UserList(r *pb.AuthUserListRequest) (*pb.AuthUserListResponse, error) {
 	tx := as.be.BatchTx()
 	tx.Lock()
-	users := getAllUsers(tx)
+	users := getAllUsers(as.lg, tx)
 	tx.Unlock()
 
 	resp := &pb.AuthUserListResponse{Users: make([]string, len(users))}
@@ -505,7 +584,15 @@ func (as *authStore) UserList(r *pb.AuthUserListRequest) (*pb.AuthUserListRespon
 
 func (as *authStore) UserRevokeRole(r *pb.AuthUserRevokeRoleRequest) (*pb.AuthUserRevokeRoleResponse, error) {
 	if as.enabled && strings.Compare(r.Name, rootUser) == 0 && strings.Compare(r.Role, rootRole) == 0 {
-		plog.Errorf("the role root must not be revoked from the user root")
+		if as.lg != nil {
+			as.lg.Warn(
+				"'root' user cannot revoke 'root' role",
+				zap.String("user-name", r.Name),
+				zap.String("role-name", r.Role),
+			)
+		} else {
+			plog.Errorf("the role root must not be revoked from the user root")
+		}
 		return nil, ErrInvalidAuthMgmt
 	}
 
@@ -513,7 +600,7 @@ func (as *authStore) UserRevokeRole(r *pb.AuthUserRevokeRoleRequest) (*pb.AuthUs
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, r.Name)
+	user := getUser(as.lg, tx, r.Name)
 	if user == nil {
 		return nil, ErrUserNotFound
 	}
@@ -533,13 +620,23 @@ func (as *authStore) UserRevokeRole(r *pb.AuthUserRevokeRoleRequest) (*pb.AuthUs
 		return nil, ErrRoleNotGranted
 	}
 
-	putUser(tx, updatedUser)
+	putUser(as.lg, tx, updatedUser)
 
 	as.invalidateCachedPerm(r.Name)
 
 	as.commitRevision(tx)
 
-	plog.Noticef("revoked role %s from user %s", r.Role, r.Name)
+	if as.lg != nil {
+		as.lg.Info(
+			"revoked a role from a user",
+			zap.String("user-name", r.Name),
+			zap.Strings("old-user-roles", user.Roles),
+			zap.Strings("new-user-roles", updatedUser.Roles),
+			zap.String("revoked-role-name", r.Role),
+		)
+	} else {
+		plog.Noticef("revoked role %s from user %s", r.Role, r.Name)
+	}
 	return &pb.AuthUserRevokeRoleResponse{}, nil
 }
 
@@ -561,7 +658,7 @@ func (as *authStore) RoleGet(r *pb.AuthRoleGetRequest) (*pb.AuthRoleGetResponse,
 func (as *authStore) RoleList(r *pb.AuthRoleListRequest) (*pb.AuthRoleListResponse, error) {
 	tx := as.be.BatchTx()
 	tx.Lock()
-	roles := getAllRoles(tx)
+	roles := getAllRoles(as.lg, tx)
 	tx.Unlock()
 
 	resp := &pb.AuthRoleListResponse{Roles: make([]string, len(roles))}
@@ -595,7 +692,7 @@ func (as *authStore) RoleRevokePermission(r *pb.AuthRoleRevokePermissionRequest)
 		return nil, ErrPermissionNotGranted
 	}
 
-	putRole(tx, updatedRole)
+	putRole(as.lg, tx, updatedRole)
 
 	// TODO(mitake): currently single role update invalidates every cache
 	// It should be optimized.
@@ -603,13 +700,26 @@ func (as *authStore) RoleRevokePermission(r *pb.AuthRoleRevokePermissionRequest)
 
 	as.commitRevision(tx)
 
-	plog.Noticef("revoked key %s from role %s", r.Key, r.Role)
+	if as.lg != nil {
+		as.lg.Info(
+			"revoked a permission on range",
+			zap.String("role-name", r.Role),
+			zap.String("key", string(r.Key)),
+			zap.String("range-end", string(r.RangeEnd)),
+		)
+	} else {
+		plog.Noticef("revoked key %s from role %s", r.Key, r.Role)
+	}
 	return &pb.AuthRoleRevokePermissionResponse{}, nil
 }
 
 func (as *authStore) RoleDelete(r *pb.AuthRoleDeleteRequest) (*pb.AuthRoleDeleteResponse, error) {
 	if as.enabled && strings.Compare(r.Role, rootRole) == 0 {
-		plog.Errorf("the role root must not be deleted")
+		if as.lg != nil {
+			as.lg.Warn("cannot delete 'root' role", zap.String("role-name", r.Role))
+		} else {
+			plog.Errorf("the role root must not be deleted")
+		}
 		return nil, ErrInvalidAuthMgmt
 	}
 
@@ -624,7 +734,7 @@ func (as *authStore) RoleDelete(r *pb.AuthRoleDeleteRequest) (*pb.AuthRoleDelete
 
 	delRole(tx, r.Role)
 
-	users := getAllUsers(tx)
+	users := getAllUsers(as.lg, tx)
 	for _, user := range users {
 		updatedUser := &authpb.User{
 			Name:     user.Name,
@@ -641,14 +751,18 @@ func (as *authStore) RoleDelete(r *pb.AuthRoleDeleteRequest) (*pb.AuthRoleDelete
 			continue
 		}
 
-		putUser(tx, updatedUser)
+		putUser(as.lg, tx, updatedUser)
 
 		as.invalidateCachedPerm(string(user.Name))
 	}
 
 	as.commitRevision(tx)
 
-	plog.Noticef("deleted role %s", r.Role)
+	if as.lg != nil {
+		as.lg.Info("deleted a role", zap.String("role-name", r.Role))
+	} else {
+		plog.Noticef("deleted role %s", r.Role)
+	}
 	return &pb.AuthRoleDeleteResponse{}, nil
 }
 
@@ -666,12 +780,15 @@ func (as *authStore) RoleAdd(r *pb.AuthRoleAddRequest) (*pb.AuthRoleAddResponse,
 		Name: []byte(r.Name),
 	}
 
-	putRole(tx, newRole)
+	putRole(as.lg, tx, newRole)
 
 	as.commitRevision(tx)
 
-	plog.Noticef("Role %s is created", r.Name)
-
+	if as.lg != nil {
+		as.lg.Info("created a role", zap.String("role-name", r.Name))
+	} else {
+		plog.Noticef("Role %s is created", r.Name)
+	}
 	return &pb.AuthRoleAddResponse{}, nil
 }
 
@@ -722,7 +839,7 @@ func (as *authStore) RoleGrantPermission(r *pb.AuthRoleGrantPermissionRequest) (
 		sort.Sort(permSlice(role.KeyPermission))
 	}
 
-	putRole(tx, role)
+	putRole(as.lg, tx, role)
 
 	// TODO(mitake): currently single role update invalidates every cache
 	// It should be optimized.
@@ -730,8 +847,15 @@ func (as *authStore) RoleGrantPermission(r *pb.AuthRoleGrantPermissionRequest) (
 
 	as.commitRevision(tx)
 
-	plog.Noticef("role %s's permission of key %s is updated as %s", r.Name, r.Perm.Key, authpb.Permission_Type_name[int32(r.Perm.PermType)])
-
+	if as.lg != nil {
+		as.lg.Info(
+			"granted/updated a permission to a user",
+			zap.String("user-name", r.Name),
+			zap.String("permission-name", authpb.Permission_Type_name[int32(r.Perm.PermType)]),
+		)
+	} else {
+		plog.Noticef("role %s's permission of key %s is updated as %s", r.Name, r.Perm.Key, authpb.Permission_Type_name[int32(r.Perm.PermType)])
+	}
 	return &pb.AuthRoleGrantPermissionResponse{}, nil
 }
 
@@ -754,9 +878,13 @@ func (as *authStore) isOpPermitted(userName string, revision uint64, key, rangeE
 	tx.Lock()
 	defer tx.Unlock()
 
-	user := getUser(tx, userName)
+	user := getUser(as.lg, tx, userName)
 	if user == nil {
-		plog.Errorf("invalid user name %s for permission checking", userName)
+		if as.lg != nil {
+			as.lg.Warn("cannot find a user for permission check", zap.String("user-name", userName))
+		} else {
+			plog.Errorf("invalid user name %s for permission checking", userName)
+		}
 		return ErrPermissionDenied
 	}
 
@@ -794,7 +922,7 @@ func (as *authStore) IsAdminPermitted(authInfo *AuthInfo) error {
 
 	tx := as.be.BatchTx()
 	tx.Lock()
-	u := getUser(tx, authInfo.Username)
+	u := getUser(as.lg, tx, authInfo.Username)
 	tx.Unlock()
 
 	if u == nil {
@@ -808,7 +936,7 @@ func (as *authStore) IsAdminPermitted(authInfo *AuthInfo) error {
 	return nil
 }
 
-func getUser(tx backend.BatchTx, username string) *authpb.User {
+func getUser(lg *zap.Logger, tx backend.BatchTx, username string) *authpb.User {
 	_, vs := tx.UnsafeRange(authUsersBucketName, []byte(username), nil, 0)
 	if len(vs) == 0 {
 		return nil
@@ -817,12 +945,20 @@ func getUser(tx backend.BatchTx, username string) *authpb.User {
 	user := &authpb.User{}
 	err := user.Unmarshal(vs[0])
 	if err != nil {
-		plog.Panicf("failed to unmarshal user struct (name: %s): %s", username, err)
+		if lg != nil {
+			lg.Panic(
+				"failed to unmarshal 'authpb.User'",
+				zap.String("user-name", username),
+				zap.Error(err),
+			)
+		} else {
+			plog.Panicf("failed to unmarshal user struct (name: %s): %s", username, err)
+		}
 	}
 	return user
 }
 
-func getAllUsers(tx backend.BatchTx) []*authpb.User {
+func getAllUsers(lg *zap.Logger, tx backend.BatchTx) []*authpb.User {
 	_, vs := tx.UnsafeRange(authUsersBucketName, []byte{0}, []byte{0xff}, -1)
 	if len(vs) == 0 {
 		return nil
@@ -833,17 +969,25 @@ func getAllUsers(tx backend.BatchTx) []*authpb.User {
 		user := &authpb.User{}
 		err := user.Unmarshal(vs[i])
 		if err != nil {
-			plog.Panicf("failed to unmarshal user struct: %s", err)
+			if lg != nil {
+				lg.Panic("failed to unmarshal 'authpb.User'", zap.Error(err))
+			} else {
+				plog.Panicf("failed to unmarshal user struct: %s", err)
+			}
 		}
 		users[i] = user
 	}
 	return users
 }
 
-func putUser(tx backend.BatchTx, user *authpb.User) {
+func putUser(lg *zap.Logger, tx backend.BatchTx, user *authpb.User) {
 	b, err := user.Marshal()
 	if err != nil {
-		plog.Panicf("failed to marshal user struct (name: %s): %s", user.Name, err)
+		if lg != nil {
+			lg.Panic("failed to unmarshal 'authpb.User'", zap.Error(err))
+		} else {
+			plog.Panicf("failed to marshal user struct (name: %s): %s", user.Name, err)
+		}
 	}
 	tx.UnsafePut(authUsersBucketName, user.Name, b)
 }
@@ -866,7 +1010,7 @@ func getRole(tx backend.BatchTx, rolename string) *authpb.Role {
 	return role
 }
 
-func getAllRoles(tx backend.BatchTx) []*authpb.Role {
+func getAllRoles(lg *zap.Logger, tx backend.BatchTx) []*authpb.Role {
 	_, vs := tx.UnsafeRange(authRolesBucketName, []byte{0}, []byte{0xff}, -1)
 	if len(vs) == 0 {
 		return nil
@@ -877,17 +1021,29 @@ func getAllRoles(tx backend.BatchTx) []*authpb.Role {
 		role := &authpb.Role{}
 		err := role.Unmarshal(vs[i])
 		if err != nil {
-			plog.Panicf("failed to unmarshal role struct: %s", err)
+			if lg != nil {
+				lg.Panic("failed to unmarshal 'authpb.Role'", zap.Error(err))
+			} else {
+				plog.Panicf("failed to unmarshal role struct: %s", err)
+			}
 		}
 		roles[i] = role
 	}
 	return roles
 }
 
-func putRole(tx backend.BatchTx, role *authpb.Role) {
+func putRole(lg *zap.Logger, tx backend.BatchTx, role *authpb.Role) {
 	b, err := role.Marshal()
 	if err != nil {
-		plog.Panicf("failed to marshal role struct (name: %s): %s", role.Name, err)
+		if lg != nil {
+			lg.Panic(
+				"failed to marshal 'authpb.Role'",
+				zap.String("role-name", string(role.Name)),
+				zap.Error(err),
+			)
+		} else {
+			plog.Panicf("failed to marshal role struct (name: %s): %s", role.Name, err)
+		}
 	}
 
 	tx.UnsafePut(authRolesBucketName, []byte(role.Name), b)
@@ -903,7 +1059,8 @@ func (as *authStore) IsAuthEnabled() bool {
 	return as.enabled
 }
 
-func NewAuthStore(be backend.Backend, tp TokenProvider) *authStore {
+// NewAuthStore creates a new AuthStore.
+func NewAuthStore(lg *zap.Logger, be backend.Backend, tp TokenProvider) *authStore {
 	tx := be.BatchTx()
 	tx.Lock()
 
@@ -920,8 +1077,9 @@ func NewAuthStore(be backend.Backend, tp TokenProvider) *authStore {
 	}
 
 	as := &authStore{
-		be:             be,
 		revision:       getRevision(tx),
+		lg:             lg,
+		be:             be,
 		enabled:        enabled,
 		rangePermCache: make(map[string]*unifiedRangePermissions),
 		tokenProvider:  tp,
@@ -960,7 +1118,6 @@ func getRevision(tx backend.BatchTx) uint64 {
 		// this can happen in the initialization phase
 		return 0
 	}
-
 	return binary.BigEndian.Uint64(vs[0])
 }
 
@@ -982,12 +1139,12 @@ func (as *authStore) AuthInfoFromTLS(ctx context.Context) *AuthInfo {
 	for _, chains := range tlsInfo.State.VerifiedChains {
 		for _, chain := range chains {
 			cn := chain.Subject.CommonName
-			plog.Debugf("found common name %s", cn)
-
-			return &AuthInfo{
-				Username: cn,
-				Revision: as.Revision(),
+			if as.lg != nil {
+				as.lg.Debug("found command name", zap.String("common-name", cn))
+			} else {
+				plog.Debugf("found common name %s", cn)
 			}
+			return &AuthInfo{Username: cn, Revision: as.Revision()}
 		}
 	}
 
@@ -1012,7 +1169,11 @@ func (as *authStore) AuthInfoFromCtx(ctx context.Context) (*AuthInfo, error) {
 	token := ts[0]
 	authInfo, uok := as.authInfoFromToken(ctx, token)
 	if !uok {
-		plog.Warningf("invalid auth token: %s", token)
+		if as.lg != nil {
+			as.lg.Warn("invalid auth token", zap.String("token", token))
+		} else {
+			plog.Warningf("invalid auth token: %s", token)
+		}
 		return nil, ErrInvalidAuthToken
 	}
 
@@ -1023,7 +1184,7 @@ func (as *authStore) GenTokenPrefix() (string, error) {
 	return as.tokenProvider.genTokenPrefix()
 }
 
-func decomposeOpts(optstr string) (string, map[string]string, error) {
+func decomposeOpts(lg *zap.Logger, optstr string) (string, map[string]string, error) {
 	opts := strings.Split(optstr, ",")
 	tokenType := opts[0]
 
@@ -1032,12 +1193,24 @@ func decomposeOpts(optstr string) (string, map[string]string, error) {
 		pair := strings.Split(opts[i], "=")
 
 		if len(pair) != 2 {
-			plog.Errorf("invalid token specific option: %s", optstr)
+			if lg != nil {
+				lg.Warn("invalid token option", zap.String("option", optstr))
+			} else {
+				plog.Errorf("invalid token specific option: %s", optstr)
+			}
 			return "", nil, ErrInvalidAuthOpts
 		}
 
 		if _, ok := typeSpecificOpts[pair[0]]; ok {
-			plog.Errorf("invalid token specific option, duplicated parameters (%s): %s", pair[0], optstr)
+			if lg != nil {
+				lg.Warn(
+					"invalid token option",
+					zap.String("option", optstr),
+					zap.String("duplicate-parameter", pair[0]),
+				)
+			} else {
+				plog.Errorf("invalid token specific option, duplicated parameters (%s): %s", pair[0], optstr)
+			}
 			return "", nil, ErrInvalidAuthOpts
 		}
 
@@ -1048,8 +1221,12 @@ func decomposeOpts(optstr string) (string, map[string]string, error) {
 
 }
 
-func NewTokenProvider(lg *zap.Logger, tokenOpts string, indexWaiter func(uint64) <-chan struct{}) (TokenProvider, error) {
-	tokenType, typeSpecificOpts, err := decomposeOpts(tokenOpts)
+// NewTokenProvider creates a new token provider.
+func NewTokenProvider(
+	lg *zap.Logger,
+	tokenOpts string,
+	indexWaiter func(uint64) <-chan struct{}) (TokenProvider, error) {
+	tokenType, typeSpecificOpts, err := decomposeOpts(lg, tokenOpts)
 	if err != nil {
 		return nil, ErrInvalidAuthOpts
 	}
@@ -1061,14 +1238,21 @@ func NewTokenProvider(lg *zap.Logger, tokenOpts string, indexWaiter func(uint64)
 		} else {
 			plog.Warningf("simple token is not cryptographically signed")
 		}
-		return newTokenProviderSimple(indexWaiter), nil
+		return newTokenProviderSimple(lg, indexWaiter), nil
+
 	case "jwt":
-		return newTokenProviderJWT(typeSpecificOpts)
+		return newTokenProviderJWT(lg, typeSpecificOpts)
+
 	case "":
 		return newTokenProviderNop()
+
 	default:
 		if lg != nil {
-			lg.Warn("unknown token type", zap.String("type", tokenType), zap.Error(ErrInvalidAuthOpts))
+			lg.Warn(
+				"unknown token type",
+				zap.String("type", tokenType),
+				zap.Error(ErrInvalidAuthOpts),
+			)
 		} else {
 			plog.Errorf("unknown token type: %s", tokenType)
 		}
@@ -1086,7 +1270,14 @@ func (as *authStore) WithRoot(ctx context.Context) context.Context {
 		ctx1 := context.WithValue(ctx, AuthenticateParamIndex{}, uint64(0))
 		prefix, err := ts.genTokenPrefix()
 		if err != nil {
-			plog.Errorf("failed to generate prefix of internally used token")
+			if as.lg != nil {
+				as.lg.Warn(
+					"failed to generate prefix of internally used token",
+					zap.Error(err),
+				)
+			} else {
+				plog.Errorf("failed to generate prefix of internally used token")
+			}
 			return ctx
 		}
 		ctxForAssign = context.WithValue(ctx1, AuthenticateParamSimpleTokenPrefix{}, prefix)
@@ -1097,7 +1288,14 @@ func (as *authStore) WithRoot(ctx context.Context) context.Context {
 	token, err := as.tokenProvider.assign(ctxForAssign, "root", as.Revision())
 	if err != nil {
 		// this must not happen
-		plog.Errorf("failed to assign token for lease revoking: %s", err)
+		if as.lg != nil {
+			as.lg.Warn(
+				"failed to assign token for lease revoking",
+				zap.Error(err),
+			)
+		} else {
+			plog.Errorf("failed to assign token for lease revoking: %s", err)
+		}
 		return ctx
 	}
 
@@ -1113,11 +1311,19 @@ func (as *authStore) WithRoot(ctx context.Context) context.Context {
 func (as *authStore) HasRole(user, role string) bool {
 	tx := as.be.BatchTx()
 	tx.Lock()
-	u := getUser(tx, user)
+	u := getUser(as.lg, tx, user)
 	tx.Unlock()
 
 	if u == nil {
-		plog.Warningf("tried to check user %s has role %s, but user %s doesn't exist", user, role, user)
+		if as.lg != nil {
+			as.lg.Warn(
+				"'has-role' requested for non-existing user",
+				zap.String("user-name", user),
+				zap.String("role-name", role),
+			)
+		} else {
+			plog.Warningf("tried to check user %s has role %s, but user %s doesn't exist", user, role, user)
+		}
 		return false
 	}
 
@@ -1126,6 +1332,5 @@ func (as *authStore) HasRole(user, role string) bool {
 			return true
 		}
 	}
-
 	return false
 }

+ 7 - 7
auth/store_test.go

@@ -54,7 +54,7 @@ func TestNewAuthStoreRevision(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	as := NewAuthStore(b, tp)
+	as := NewAuthStore(zap.NewExample(), b, tp)
 	err = enableAuthAndCreateRoot(as)
 	if err != nil {
 		t.Fatal(err)
@@ -65,7 +65,7 @@ func TestNewAuthStoreRevision(t *testing.T) {
 
 	// no changes to commit
 	b2 := backend.NewDefaultBackend(tPath)
-	as = NewAuthStore(b2, tp)
+	as = NewAuthStore(zap.NewExample(), b2, tp)
 	new := as.Revision()
 	b2.Close()
 	as.Close()
@@ -82,7 +82,7 @@ func setupAuthStore(t *testing.T) (store *authStore, teardownfunc func(t *testin
 	if err != nil {
 		t.Fatal(err)
 	}
-	as := NewAuthStore(b, tp)
+	as := NewAuthStore(zap.NewExample(), b, tp)
 	err = enableAuthAndCreateRoot(as)
 	if err != nil {
 		t.Fatal(err)
@@ -519,7 +519,7 @@ func TestAuthInfoFromCtxRace(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	as := NewAuthStore(b, tp)
+	as := NewAuthStore(zap.NewExample(), b, tp)
 	defer as.Close()
 
 	donec := make(chan struct{})
@@ -585,7 +585,7 @@ func TestRecoverFromSnapshot(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	as2 := NewAuthStore(as.be, tp)
+	as2 := NewAuthStore(zap.NewExample(), as.be, tp)
 	defer func(a *authStore) {
 		a.Close()
 	}(as2)
@@ -667,7 +667,7 @@ func TestRolesOrder(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	as := NewAuthStore(b, tp)
+	as := NewAuthStore(zap.NewExample(), b, tp)
 	err = enableAuthAndCreateRoot(as)
 	if err != nil {
 		t.Fatal(err)
@@ -713,7 +713,7 @@ func TestAuthInfoFromCtxWithRoot(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	as := NewAuthStore(b, tp)
+	as := NewAuthStore(zap.NewExample(), b, tp)
 	defer as.Close()
 
 	if err = enableAuthAndCreateRoot(as); err != nil {