From da3b7e511ffeb188d5b2f14c399e6c956c2bb30a Mon Sep 17 00:00:00 2001 From: Suhong Qin <51539171+sqin2019@users.noreply.github.com> Date: Tue, 10 Jan 2023 14:41:38 -0800 Subject: [PATCH] clean up: replace print style logging with loose-typed structured style (#164) * replace print stype logging with loose-typed structured style * additional test --- cmd/cert-rotation/main.go | 9 ++++--- cmd/justification/main.go | 5 ++-- cmd/manual-cert-actions/main.go | 7 +++--- cmd/public-key/main.go | 3 +-- go.mod | 2 +- pkg/jvscrypto/key_hosting.go | 2 +- pkg/jvscrypto/rotation_handler.go | 33 +++++++++++++------------- pkg/jvscrypto/rotation_handler_test.go | 22 +++++++++++++++++ 8 files changed, 50 insertions(+), 33 deletions(-) diff --git a/cmd/cert-rotation/main.go b/cmd/cert-rotation/main.go index d8d57f4b..185b0260 100644 --- a/cmd/cert-rotation/main.go +++ b/cmd/cert-rotation/main.go @@ -31,7 +31,6 @@ import ( "github.com/abcxyz/pkg/cfgloader" "github.com/abcxyz/pkg/logging" "github.com/hashicorp/go-multierror" - "go.uber.org/zap" ) type server struct { @@ -41,7 +40,7 @@ type server struct { // ServeHTTP rotates a single key's versions. func (s *server) ServeHTTP(w http.ResponseWriter, r *http.Request) { logger := logging.FromContext(r.Context()) - logger.Info("received request", zap.Any("url", r.URL)) + logger.Infow("received request", "url", r.URL) var errs error // TODO: load keys from DB instead. https://github.com/abcxyz/jvs/issues/17 @@ -50,10 +49,10 @@ func (s *server) ServeHTTP(w http.ResponseWriter, r *http.Request) { errs = multierror.Append(errs, fmt.Errorf("error while rotating key %s: %w", key, err)) continue } - logger.Info("successfully performed actions (if necessary) on key.", zap.String("key", key)) + logger.Infow("successfully performed actions (if necessary) on key.", "key", key) } if errs != nil { - logger.Error("ran into errors while rotating keys", zap.Error(errs)) + logger.Errorw("ran into errors while rotating keys", "errors", errs) http.Error(w, "error while rotating keys", http.StatusInternalServerError) return } @@ -109,7 +108,7 @@ func realMain(ctx context.Context) error { port := os.Getenv("PORT") if port == "" { port = "8080" - logger.Debug("defaulting to port ", zap.String("port", port)) + logger.Debugw("defaulting to port ", "port", port) } // Create the server and listen in a goroutine. diff --git a/cmd/justification/main.go b/cmd/justification/main.go index 395b585c..68d3505b 100644 --- a/cmd/justification/main.go +++ b/cmd/justification/main.go @@ -30,7 +30,6 @@ import ( "github.com/abcxyz/pkg/grpcutil" "github.com/abcxyz/pkg/logging" "go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc" - "go.uber.org/zap" "golang.org/x/sync/errgroup" "google.golang.org/grpc" "google.golang.org/grpc/reflection" @@ -47,7 +46,7 @@ func main() { done() logger.Fatal(err) } - logger.Infof("successful shutdown") + logger.Info("successful shutdown") } func realMain(ctx context.Context) error { @@ -90,7 +89,7 @@ func realMain(ctx context.Context) error { // https://github.com/grpc/grpc/blob/master/doc/health-checking.md g, ctx := errgroup.WithContext(ctx) g.Go(func() error { - logger.Debugf("server listening at", zap.Any("address", lis.Addr())) + logger.Debugw("server listening at", "address", lis.Addr()) return s.Serve(lis) }) diff --git a/cmd/manual-cert-actions/main.go b/cmd/manual-cert-actions/main.go index 6e4e3d06..95e04dbd 100644 --- a/cmd/manual-cert-actions/main.go +++ b/cmd/manual-cert-actions/main.go @@ -30,7 +30,6 @@ import ( "github.com/abcxyz/pkg/cfgloader" "github.com/abcxyz/pkg/logging" "go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc" - "go.uber.org/zap" "golang.org/x/sync/errgroup" "google.golang.org/grpc" "google.golang.org/grpc/reflection" @@ -47,7 +46,7 @@ func main() { done() logger.Fatal(err) } - logger.Infof("successful shutdown") + logger.Info("successful shutdown") } func realMain(ctx context.Context) error { @@ -86,7 +85,7 @@ func realMain(ctx context.Context) error { port := os.Getenv("PORT") if port == "" { port = "8080" - logger.Debug("defaulting to port ", zap.String("port", port)) + logger.Debugw("defaulting to port ", "port", port) } lis, err := net.Listen("tcp", ":"+port) @@ -98,7 +97,7 @@ func realMain(ctx context.Context) error { // https://github.com/grpc/grpc/blob/master/doc/health-checking.md g, ctx := errgroup.WithContext(ctx) g.Go(func() error { - logger.Debugf("server listening at", zap.Any("address", lis.Addr())) + logger.Debugw("server listening at", "address", lis.Addr()) return s.Serve(lis) }) diff --git a/cmd/public-key/main.go b/cmd/public-key/main.go index 47452fee..a29caa3f 100644 --- a/cmd/public-key/main.go +++ b/cmd/public-key/main.go @@ -31,7 +31,6 @@ import ( "github.com/abcxyz/pkg/cache" "github.com/abcxyz/pkg/cfgloader" "github.com/abcxyz/pkg/logging" - "go.uber.org/zap" ) func main() { @@ -81,7 +80,7 @@ func realMain(ctx context.Context) error { mux.Handle("/.well-known/jwks", ks) // Create the server and listen in a goroutine. - logger.Debug("starting server on port", zap.String("port", cfg.Port)) + logger.Debugw("starting server on port", "port", cfg.Port) server := &http.Server{ Addr: ":" + cfg.Port, Handler: mux, diff --git a/go.mod b/go.mod index 6ef5dfa9..2886f280 100644 --- a/go.mod +++ b/go.mod @@ -17,7 +17,6 @@ require ( github.com/spf13/cobra v1.5.0 github.com/spf13/viper v1.13.0 go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.36.1 - go.uber.org/zap v1.23.0 golang.org/x/oauth2 v0.0.0-20221006150949-b44042a4b9c1 golang.org/x/sync v0.0.0-20220929204114-8fcdb60fdcc0 google.golang.org/api v0.98.0 @@ -60,6 +59,7 @@ require ( go.opentelemetry.io/otel/trace v1.10.0 // indirect go.uber.org/atomic v1.10.0 // indirect go.uber.org/multierr v1.8.0 // indirect + go.uber.org/zap v1.23.0 // indirect golang.org/x/crypto v0.0.0-20221010152910-d6f0a8c073c2 // indirect golang.org/x/net v0.0.0-20221004154528-8021a29435af // indirect golang.org/x/sys v0.0.0-20221010170243-090e33056c14 // indirect diff --git a/pkg/jvscrypto/key_hosting.go b/pkg/jvscrypto/key_hosting.go index 509779f4..8ad52681 100644 --- a/pkg/jvscrypto/key_hosting.go +++ b/pkg/jvscrypto/key_hosting.go @@ -43,7 +43,7 @@ func (k *KeyServer) ServeHTTP(w http.ResponseWriter, r *http.Request) { return k.generateJWKString(r.Context()) }) if err != nil { - logger.Error("error generating jwk string", err) + logger.Errorw("error generating jwk string", "error", err) http.Error(w, "error generating jwk string", http.StatusInternalServerError) return } diff --git a/pkg/jvscrypto/rotation_handler.go b/pkg/jvscrypto/rotation_handler.go index 2b9e0c88..063c6281 100644 --- a/pkg/jvscrypto/rotation_handler.go +++ b/pkg/jvscrypto/rotation_handler.go @@ -23,7 +23,6 @@ import ( "github.com/abcxyz/jvs/pkg/config" "github.com/abcxyz/pkg/logging" - "go.uber.org/zap" "google.golang.org/protobuf/types/known/fieldmaskpb" kms "cloud.google.com/go/kms/apiv1" @@ -101,7 +100,7 @@ func (h *RotationHandler) determineActions(ctx context.Context, vers []*kmspb.Cr var newerVers []*kmspb.CryptoKeyVersion for _, ver := range vers { - logger.Debug("checking version", zap.Any("version", ver)) + logger.Debugw("checking version", "version", ver) if primaryName != "" && ver.Name == primaryName { primary = ver break @@ -117,10 +116,10 @@ func (h *RotationHandler) determineActions(ctx context.Context, vers []*kmspb.Cr continue } if createdBefore(ver, primary) { - logger.Debug("version is older", zap.Any("version", ver)) + logger.Debugw("version is older", "version", ver) olderVers = append(olderVers, ver) } else { - logger.Debug("version is newer", zap.Any("version", ver)) + logger.Debugw("version is newer", "version", ver) newerVers = append(newerVers, ver) } } @@ -196,7 +195,7 @@ func (h *RotationHandler) actionsForOlderVersions(ctx context.Context, vers []*k actions = append(actions, &actionTuple{ActionDestroy, ver}) } default: - logger.Info("no action needed for key version in current state.", zap.Any("version", ver), zap.Any("state", ver.State)) + logger.Infow("no action needed for key version in current state.", "version", ver, "state", ver.State) } } return actions @@ -207,9 +206,9 @@ func (h *RotationHandler) shouldDestroy(ctx context.Context, ver *kmspb.CryptoKe cutoff := curTime.Add(-h.CryptoConfig.DestroyAge()) shouldDestroy := ver.CreateTime.AsTime().Before(cutoff) if shouldDestroy { - logger.Info("version created before cutoff date, should destroy.", zap.Any("version", ver), zap.Any("cutoff", cutoff)) + logger.Infow("version created before cutoff date, should destroy.", "version", ver, "cutoff", cutoff) } else { - logger.Debug("version created after cutoff date, no action necessary.", zap.Any("version", ver), zap.Any("cutoff", cutoff)) + logger.Debugw("version created after cutoff date, no action necessary.", "version", ver, "cutoff", cutoff) } return shouldDestroy } @@ -219,9 +218,9 @@ func (h *RotationHandler) shouldDisable(ctx context.Context, ver *kmspb.CryptoKe cutoff := curTime.Add(-h.CryptoConfig.KeyTTL) shouldDisable := ver.CreateTime.AsTime().Before(cutoff) if shouldDisable { - logger.Info("version created before cutoff date, should disable.", zap.Any("version", ver), zap.Any("cutoff", cutoff)) + logger.Infow("version created before cutoff date, should disable.", "version", ver, "cutoff", cutoff) } else { - logger.Debug("version created after cutoff date, no action necessary.", zap.Any("version", ver), zap.Any("cutoff", cutoff)) + logger.Debugw("version created after cutoff date, no action necessary.", "version", ver, "cutoff", cutoff) } return shouldDisable } @@ -231,15 +230,15 @@ func (h *RotationHandler) shouldDisable(ctx context.Context, ver *kmspb.CryptoKe func (h *RotationHandler) shouldRotate(ctx context.Context, primary, newest *kmspb.CryptoKeyVersion, curTime time.Time) bool { logger := logging.FromContext(ctx) if newest != nil { - logger.Debug("new version already created, no action necessary.", zap.Any("version", newest)) + logger.Debugw("new version already created, no action necessary.", "version", newest) return false } cutoff := curTime.Add(-h.CryptoConfig.RotationAge()) shouldRotate := primary.CreateTime.AsTime().Before(cutoff) if shouldRotate { - logger.Info("version created before cutoff date, should rotate.", zap.Any("version", primary), zap.Any("cutoff", cutoff)) + logger.Infow("version created before cutoff date, should rotate.", "version", primary, "cutoff", cutoff) } else { - logger.Debug("version created after cutoff date, no action necessary.", zap.Any("version", primary), zap.Any("cutoff", cutoff)) + logger.Debugw("version created after cutoff date, no action necessary.", "version", primary, "cutoff", cutoff) } return shouldRotate } @@ -252,15 +251,15 @@ func (h *RotationHandler) shouldPromote(ctx context.Context, primary, newest *km return false } if primary == nil { - logger.Info("primary does not exist, should promote the newest key to primary regardless of propagation delay.", zap.Any("version", newest)) + logger.Infow("primary does not exist, should promote the newest key to primary regardless of propagation delay.", "version", newest) return true } cutoff := curTime.Add(-h.CryptoConfig.PropagationDelay) canPromote := newest.CreateTime.AsTime().Before(cutoff) if canPromote { - logger.Info("version created before cutoff date, should promote to primary.", zap.Any("version", newest), zap.Any("cutoff", cutoff)) + logger.Infow("version created before cutoff date, should promote to primary.", "version", newest, "cutoff", cutoff) } else { - logger.Debug("version created after cutoff date, no action necessary.", zap.Any("version", newest), zap.Any("cutoff", cutoff)) + logger.Debugw("version created after cutoff date, no action necessary.", "version", newest, "cutoff", cutoff) } return canPromote } @@ -312,7 +311,7 @@ func (h *RotationHandler) performDisable(ctx context.Context, ver *kmspb.CryptoK // Make a copy to modify newVerState := ver - logger.Info("disabling key version", zap.String("versionName", ver.Name)) + logger.Infow("disabling key version", "versionName", ver.Name) newVerState.State = kmspb.CryptoKeyVersion_DISABLED var messageType *kmspb.CryptoKeyVersion mask, err := fieldmaskpb.New(messageType, "state") @@ -331,7 +330,7 @@ func (h *RotationHandler) performDisable(ctx context.Context, ver *kmspb.CryptoK func (h *RotationHandler) performDestroy(ctx context.Context, ver *kmspb.CryptoKeyVersion) error { logger := logging.FromContext(ctx) - logger.Info("destroying key version", zap.String("versionName", ver.Name)) + logger.Infow("destroying key version", "versionName", ver.Name) destroyReq := &kmspb.DestroyCryptoKeyVersionRequest{ Name: ver.Name, } diff --git a/pkg/jvscrypto/rotation_handler_test.go b/pkg/jvscrypto/rotation_handler_test.go index 1458e31f..73f4a5e2 100644 --- a/pkg/jvscrypto/rotation_handler_test.go +++ b/pkg/jvscrypto/rotation_handler_test.go @@ -222,6 +222,28 @@ func TestDetermineActions(t *testing.T) { {ActionPromote, newEnabledKey}, }, }, + { + name: "three_enabled_keys_no_action", + versions: []*kmspb.CryptoKeyVersion{ + oldEnabledKey, + newEnabledKey, + newEnabledKey2, + }, + primary: oldEnabledKey.Name, + wantActions: []*actionTuple{}, + }, + { + name: "three_enabled_keys_promote", + versions: []*kmspb.CryptoKeyVersion{ + oldEnabledKey2, + oldEnabledKey, + newEnabledKey, + }, + primary: oldEnabledKey2.Name, + wantActions: []*actionTuple{ + {ActionPromote, newEnabledKey}, + }, + }, { name: "three_enabled_keys", versions: []*kmspb.CryptoKeyVersion{