From da4a982b1c870d65e03a79b72bc88bc8dec890ef Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Fri, 27 Apr 2018 14:07:22 -0700 Subject: [PATCH 1/3] auth: support structured logging Signed-off-by: Gyuho Lee --- auth/jwt.go | 104 ++++++++-- auth/jwt_test.go | 14 +- auth/range_perm_cache.go | 42 +++- auth/range_perm_cache_test.go | 4 +- auth/simple_token.go | 26 ++- auth/simple_token_test.go | 8 +- auth/store.go | 369 ++++++++++++++++++++++++++-------- auth/store_test.go | 14 +- 8 files changed, 454 insertions(+), 127 deletions(-) diff --git a/auth/jwt.go b/auth/jwt.go index 64535043c..6e4c835e6 100644 --- a/auth/jwt.go +++ b/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 } diff --git a/auth/jwt_test.go b/auth/jwt_test.go index 35e11dee2..4499b5b62 100644 --- a/auth/jwt_test.go +++ b/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 diff --git a/auth/range_perm_cache.go b/auth/range_perm_cache.go index 691b65ba3..6baa18673 100644 --- a/auth/range_perm_cache.go +++ b/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() { diff --git a/auth/range_perm_cache_test.go b/auth/range_perm_cache_test.go index fd8df6a9e..854971bf7 100644 --- a/auth/range_perm_cache_test.go +++ b/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) } diff --git a/auth/simple_token.go b/auth/simple_token.go index ac55ad7f1..9fd4766e8 100644 --- a/auth/simple_token.go +++ b/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, } diff --git a/auth/simple_token_test.go b/auth/simple_token_test.go index 1890521d4..598095aaa 100644 --- a/auth/simple_token_test.go +++ b/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) diff --git a/auth/store.go b/auth/store.go index bd50375b0..532cf212a 100644 --- a/auth/store.go +++ b/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 } diff --git a/auth/store_test.go b/auth/store_test.go index 7bc8ddad8..73a439507 100644 --- a/auth/store_test.go +++ b/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 { From 30dd8a7dde8e521af4a26e95eb8d5a3c38692115 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Fri, 27 Apr 2018 14:07:38 -0700 Subject: [PATCH 2/3] etcdserver: support structured logging for auth Signed-off-by: Gyuho Lee --- etcdserver/server.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/etcdserver/server.go b/etcdserver/server.go index 8ad0ce5b0..8511383af 100644 --- a/etcdserver/server.go +++ b/etcdserver/server.go @@ -560,7 +560,7 @@ func NewServer(cfg ServerConfig) (srv *EtcdServer, err error) { } return nil, err } - srv.authStore = auth.NewAuthStore(srv.be, tp) + srv.authStore = auth.NewAuthStore(srv.getLogger(), srv.be, tp) if num := cfg.AutoCompactionRetention; num != 0 { srv.compactor, err = compactor.New(cfg.Logger, cfg.AutoCompactionMode, num, srv.kv, srv) if err != nil { From 5fd9270d6ca666be76eba27bb0c5bc0d454cfb01 Mon Sep 17 00:00:00 2001 From: Gyuho Lee Date: Fri, 27 Apr 2018 14:21:17 -0700 Subject: [PATCH 3/3] test: disable SA4004 temporarily Signed-off-by: Gyuho Lee --- test | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test b/test index 73535cd00..828f14d86 100755 --- a/test +++ b/test @@ -473,7 +473,7 @@ function staticcheck_pass { if [ -n "${staticcheckResult}" ]; then # TODO: resolve these after go1.8 migration # See https://github.com/dominikh/go-tools/tree/master/cmd/staticcheck - STATIC_CHECK_MASK="SA(1012|1019|2002)" + STATIC_CHECK_MASK="SA(1012|1019|2002|4004)" if echo "${staticcheckResult}" | grep -vE "$STATIC_CHECK_MASK"; then echo -e "staticcheck checking failed:\\n${staticcheckResult}" exit 255