clean up: replace print style logging with loose-typed structured sty…

…le (#164)

* replace print stype logging with loose-typed structured style

* additional test

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.

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

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

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,

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

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
 	}

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,
 	}

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{