Add debug logging for verify command (#610)

Signed-off-by: Daniel Weiße <dw@edgeless.systems>

cli/cmd/root.go

@@ -39,7 +39,9 @@ func NewRootCmd() *cobra.Command {
 	rootCmd.SetOut(os.Stdout)
 
 	rootCmd.PersistentFlags().String("config", constants.ConfigFilename, "path to the configuration file")
-	must(rootCmd.MarkPersistentFlagFilename("config", "json"))
+	must(rootCmd.MarkPersistentFlagFilename("config", "yaml"))
+
+	rootCmd.PersistentFlags().Bool("debug", false, "enable debug logging")
 
 	rootCmd.AddCommand(cmd.NewConfigCmd())
 	rootCmd.AddCommand(cmd.NewCreateCmd())

cli/internal/cmd/log.go

@@ -0,0 +1,31 @@
+/*
+Copyright (c) Edgeless Systems GmbH
+
+SPDX-License-Identifier: AGPL-3.0-only
+*/
+
+package cmd
+
+import (
+	"github.com/edgelesssys/constellation/v2/internal/logger"
+	"github.com/spf13/cobra"
+	"go.uber.org/zap/zapcore"
+)
+
+type debugLog interface {
+	Debugf(format string, args ...any)
+	Sync()
+}
+
+func newCLILogger(cmd *cobra.Command) (debugLog, error) {
+	logLvl := zapcore.InfoLevel
+	debugLog, err := cmd.Flags().GetBool("debug")
+	if err != nil {
+		return nil, err
+	}
+	if debugLog {
+		logLvl = zapcore.DebugLevel
+	}
+
+	return logger.New(logger.PlainLog, logLvl), nil
+}

cli/internal/cmd/verify.go

@@ -48,29 +48,48 @@ If arguments aren't specified, values are read from ` + "`" + constants.ClusterI
 	return cmd
 }
 
-func runVerify(cmd *cobra.Command, args []string) error {
+type verifyCmd struct {
-	fileHandler := file.NewHandler(afero.NewOsFs())
+	log debugLog
-	verifyClient := &constellationVerifier{dialer: dialer.New(nil, nil, &net.Dialer{})}
-	return verify(cmd, fileHandler, verifyClient)
 }
 
-func verify(cmd *cobra.Command, fileHandler file.Handler, verifyClient verifyClient) error {
+func runVerify(cmd *cobra.Command, args []string) error {
-	flags, err := parseVerifyFlags(cmd, fileHandler)
+	log, err := newCLILogger(cmd)
+	if err != nil {
+		return fmt.Errorf("creating logger: %w", err)
+	}
+	defer log.Sync()
+
+	fileHandler := file.NewHandler(afero.NewOsFs())
+	verifyClient := &constellationVerifier{
+		dialer: dialer.New(nil, nil, &net.Dialer{}),
+		log:    log,
+	}
+
+	v := &verifyCmd{log: log}
+	return v.verify(cmd, fileHandler, verifyClient)
+}
+
+func (v *verifyCmd) verify(cmd *cobra.Command, fileHandler file.Handler, verifyClient verifyClient) error {
+	flags, err := v.parseVerifyFlags(cmd, fileHandler)
 	if err != nil {
 		return err
 	}
+	v.log.Debugf("Using flags: %+v", flags)
 
+	v.log.Debugf("Loading config file from %s", flags.configPath)
 	conf, err := config.New(fileHandler, flags.configPath)
 	if err != nil {
 		return displayConfigValidationErrors(cmd.ErrOrStderr(), err)
 	}
 
 	provider := conf.GetProvider()
+	v.log.Debugf("Creating aTLS Validator for %s", provider)
 	validators, err := cloudcmd.NewValidator(provider, conf)
 	if err != nil {
 		return err
 	}
 
+	v.log.Debugf("Updating expected PCRs")
 	if err := validators.UpdateInitPCRs(flags.ownerID, flags.clusterID); err != nil {
 		return err
 	}
@@ -79,10 +98,12 @@ func verify(cmd *cobra.Command, fileHandler file.Handler, verifyClient verifyCli
 	if err != nil {
 		return err
 	}
+	v.log.Debugf("Generated random nonce: %x", nonce)
 	userData, err := crypto.GenerateRandomBytes(32)
 	if err != nil {
 		return err
 	}
+	v.log.Debugf("Generated random user data: %x", userData)
 
 	if err := verifyClient.Verify(
 		cmd.Context(),
@@ -100,25 +121,31 @@ func verify(cmd *cobra.Command, fileHandler file.Handler, verifyClient verifyCli
 	return nil
 }
 
-func parseVerifyFlags(cmd *cobra.Command, fileHandler file.Handler) (verifyFlags, error) {
+func (v *verifyCmd) parseVerifyFlags(cmd *cobra.Command, fileHandler file.Handler) (verifyFlags, error) {
 	configPath, err := cmd.Flags().GetString("config")
 	if err != nil {
 		return verifyFlags{}, fmt.Errorf("parsing config path argument: %w", err)
 	}
+	v.log.Debugf("config: %s", configPath)
+
 	ownerID := ""
 	clusterID, err := cmd.Flags().GetString("cluster-id")
 	if err != nil {
 		return verifyFlags{}, fmt.Errorf("parsing cluster-id argument: %w", err)
 	}
+	v.log.Debugf("cluster-id: %s", clusterID)
+
 	endpoint, err := cmd.Flags().GetString("node-endpoint")
 	if err != nil {
 		return verifyFlags{}, fmt.Errorf("parsing node-endpoint argument: %w", err)
 	}
+	v.log.Debugf("node-endpoint: %s", endpoint)
 
 	// Get empty values from ID file
 	emptyEndpoint := endpoint == ""
 	emptyIDs := ownerID == "" && clusterID == ""
 	if emptyEndpoint || emptyIDs {
+		v.log.Debugf("Trying to supplement empty flag values from %s", constants.ClusterIDsFileName)
 		var idFile clusterid.File
 		if err := fileHandler.ReadJSON(constants.ClusterIDsFileName, &idFile); err == nil {
 			if emptyEndpoint {
@@ -178,12 +205,14 @@ func addPortIfMissing(endpoint string, defaultPort int) (string, error) {
 
 type constellationVerifier struct {
 	dialer grpcInsecureDialer
+	log    debugLog
 }
 
 // Verify retrieves an attestation statement from the Constellation and verifies it using the validator.
 func (v *constellationVerifier) Verify(
 	ctx context.Context, endpoint string, req *verifyproto.GetAttestationRequest, validator atls.Validator,
 ) error {
+	v.log.Debugf("Dialing endpoint: %s", endpoint)
 	conn, err := v.dialer.DialInsecure(ctx, endpoint)
 	if err != nil {
 		return fmt.Errorf("dialing init server: %w", err)
@@ -192,11 +221,13 @@ func (v *constellationVerifier) Verify(
 
 	client := verifyproto.NewAPIClient(conn)
 
+	v.log.Debugf("Sending attestation request")
 	resp, err := client.GetAttestation(ctx, req)
 	if err != nil {
 		return fmt.Errorf("getting attestation: %w", err)
 	}
 
+	v.log.Debugf("Verifying attestation")
 	signedData, err := validator.Validate(resp.Attestation, req.Nonce)
 	if err != nil {
 		return fmt.Errorf("validating attestation: %w", err)

cli/internal/cmd/verify_test.go

@@ -24,6 +24,7 @@ import (
 	"github.com/edgelesssys/constellation/v2/internal/file"
 	"github.com/edgelesssys/constellation/v2/internal/grpc/dialer"
 	"github.com/edgelesssys/constellation/v2/internal/grpc/testdialer"
+	"github.com/edgelesssys/constellation/v2/internal/logger"
 	"github.com/edgelesssys/constellation/v2/internal/oid"
 	"github.com/edgelesssys/constellation/v2/verify/verifyproto"
 	"github.com/spf13/afero"
@@ -163,7 +164,8 @@ func TestVerify(t *testing.T) {
 				require.NoError(fileHandler.WriteJSON(constants.ClusterIDsFileName, tc.idFile, file.OptNone))
 			}
 
-			err := verify(cmd, fileHandler, tc.protoClient)
+			v := &verifyCmd{log: logger.NewTest(t)}
+			err := v.verify(cmd, fileHandler, tc.protoClient)
 
 			if tc.wantErr {
 				assert.Error(err)
@@ -244,7 +246,7 @@ func TestVerifyClient(t *testing.T) {
 			go verifyServer.Serve(listener)
 			defer verifyServer.GracefulStop()
 
-			verifier := &constellationVerifier{dialer: dialer}
+			verifier := &constellationVerifier{dialer: dialer, log: logger.NewTest(t)}
 			request := &verifyproto.GetAttestationRequest{
 				UserData: tc.userData,
 				Nonce:    tc.nonce,