Add debug logging to Coordinator

Signed-off-by: Daniel Weiße <[email protected]>

cmd/coordinator/enclavemain.go

@@ -32,7 +32,7 @@ func main() {
 	sealDirPrefix := filepath.Join(filepath.FromSlash("/edg"), "hostfs")
 	sealDir := util.Getenv(constants.SealDir, constants.SealDirDefault())
 	sealDir = filepath.Join(sealDirPrefix, sealDir)
-	sealer := seal.NewAESGCMSealer()
+	sealer := seal.NewAESGCMSealer(log)
 	recovery := recovery.NewSinglePartyRecovery()
 	run(log, validator, issuer, sealDir, sealer, recovery)
 }

cmd/coordinator/main.go

@@ -29,7 +29,7 @@ func main() {
 	validator := quote.NewFailValidator()
 	issuer := quote.NewFailIssuer()
 	sealDir := util.Getenv(constants.SealDir, constants.SealDirDefault())
-	sealer := seal.NewNoEnclaveSealer()
+	sealer := seal.NewNoEnclaveSealer(log)
 	recovery := recovery.NewSinglePartyRecovery()
 	run(log, validator, issuer, sealDir, sealer, recovery)
 }

cmd/coordinator/run.go

@@ -66,7 +66,7 @@ func run(log *zap.Logger, validator quote.Validator, issuer quote.Issuer, sealDi
 		go server.RunPrometheusServer(promServerAddr, log, promRegistry, eventlog)
 	}
 
-	store := stdstore.New(sealer, afero.NewOsFs(), sealDir)
+	store := stdstore.New(sealer, afero.NewOsFs(), sealDir, log)
 
 	// creating core
 	log.Info("Creating the Core object")

coordinator/clientapi/clientapi_test.go

@@ -59,7 +59,7 @@ func TestGetCertQuote(t *testing.T) {
 	rootCert, intermediateCert := test.MustSetupTestCerts(test.RecoveryPrivateKey)
 
 	prepareDefaultStore := func() store.Store {
-		s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+		s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 		require.NoError(t, wrapper.New(s).PutCertificate(constants.SKCoordinatorRootCert, rootCert))
 		require.NoError(t, wrapper.New(s).PutCertificate(constants.SKCoordinatorIntermediateCert, intermediateCert))
 		return s
@@ -114,7 +114,7 @@ func TestGetCertQuote(t *testing.T) {
 		},
 		"root certificate not set": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutCertificate(constants.SKCoordinatorIntermediateCert, intermediateCert))
 				return s
 			}(),
@@ -126,7 +126,7 @@ func TestGetCertQuote(t *testing.T) {
 		},
 		"intermediate certificate not set": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutCertificate(constants.SKCoordinatorRootCert, rootCert))
 				return s
 			}(),
@@ -186,23 +186,23 @@ func TestGetManifestSignature(t *testing.T) {
 	}{
 		"success": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, s.Put(request.Manifest, []byte("manifest")))
 				require.NoError(t, s.Put(request.ManifestSignature, []byte("signature")))
 				return s
 			}(),
 		},
 		"GetRawManifest fails": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, s.Put(request.ManifestSignature, []byte("signature")))
 				return s
 			}(),
 			wantErr: true,
 		},
 		"GetManifestSignature fails": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, s.Put(request.Manifest, []byte("manifest")))
 				return s
 			}(),
@@ -255,7 +255,7 @@ func TestGetSecrets(t *testing.T) {
 	}{
 		"success": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutSecret("secret1", manifest.Secret{
 					Type:    manifest.SecretTypePlain,
 					Private: []byte("secret"),
@@ -275,7 +275,7 @@ func TestGetSecrets(t *testing.T) {
 		},
 		"wrong state": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutSecret("secret1", manifest.Secret{
 					Type:    manifest.SecretTypePlain,
 					Private: []byte("secret"),
@@ -296,7 +296,7 @@ func TestGetSecrets(t *testing.T) {
 		},
 		"user is missing permissions": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutSecret("secret1", manifest.Secret{
 					Type:    manifest.SecretTypePlain,
 					Private: []byte("secret"),
@@ -317,7 +317,7 @@ func TestGetSecrets(t *testing.T) {
 		},
 		"secret does not exist": {
 			store: func() store.Store {
-				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+				s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 				require.NoError(t, wrapper.New(s).PutSecret("secret1", manifest.Secret{
 					Type:    manifest.SecretTypePlain,
 					Private: []byte("secret"),
@@ -410,7 +410,7 @@ func TestRecover(t *testing.T) {
 	someErr := errors.New("failed")
 	_, rootCert := test.MustSetupTestCerts(test.RecoveryPrivateKey)
 	defaultStore := func() store.Store {
-		s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+		s := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t))
 		wr := wrapper.New(s)
 		require.NoError(t, wr.PutCertificate(constants.SKCoordinatorRootCert, rootCert))
 		require.NoError(t, wr.PutRawManifest([]byte(`{}`)))
@@ -500,7 +500,7 @@ func TestRecover(t *testing.T) {
 		},
 		"GetCertificate fails": {
 			store: &fakeStore{
-				store: stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), ""),
+				store: stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)),
 			},
 			recovery: &stubRecovery{},
 			core: &fakeCore{

coordinator/clientapi/legacy_test.go

@@ -616,8 +616,8 @@ func setupAPI(t *testing.T) (*ClientAPI, wrapper.Wrapper) {
 	t.Helper()
 	require := require.New(t)
 
-	store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
 	log := zaptest.NewLogger(t)
+	store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", log)
 
 	wrapper := wrapper.New(store)
 

coordinator/constants/constants.go

@@ -59,6 +59,11 @@ const (
 	// DevModeDefault is the default logging mode.
 	DevModeDefault = "0"
 
+	// DebugLogging enables debug logs.
+	DebugLogging = "EDG_DEBUG_LOGGING"
+	// DebugLoggingDefault is the default value to use when the [DebugLogging] env variable is not set.
+	DebugLoggingDefault = "0"
+
 	// StartupManifest is a path to a manifest to start with instead of waiting for a manifest from the api.
 	StartupManifest = "EDG_STARTUP_MANIFEST"
 )

coordinator/core/certificate_test.go

@@ -47,7 +47,7 @@ func TestCertificateVerify(t *testing.T) {
 	// create core
 	validator := quote.NewMockValidator()
 	issuer := quote.NewMockIssuer()
-	stor := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
+	stor := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zapLogger)
 	recovery := recovery.NewSinglePartyRecovery()
 	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stor, recovery, zapLogger, nil, nil)
 	require.NoError(err)

coordinator/core/core.go

@@ -91,6 +91,7 @@ func (c *Core) AdvanceState(newState state.State, tx interface {
 	GetState() (state.State, error)
 },
 ) error {
+	c.log.Debug("Advancing state", zap.Int("from", int(newState)), zap.Int("to", int(newState)))
 	curState, err := tx.GetState()
 	if err != nil {
 		return err
@@ -123,6 +124,7 @@ func NewCore(
 
 	zapLogger.Info("Loading state")
 	recoveryData, loadErr := txHandle.LoadState()
+	c.log.Debug("Loaded state", zap.Error(loadErr), zap.ByteString("recoveryData", recoveryData))
 	if err := c.recovery.SetRecoveryData(recoveryData); err != nil {
 		c.log.Error("Could not retrieve recovery data from state. Recovery will be unavailable", zap.Error(err))
 	}
@@ -197,7 +199,7 @@ func NewCoreWithMocks() *Core {
 	issuer := quote.NewMockIssuer()
 	sealer := &seal.MockSealer{}
 	recovery := recovery.NewSinglePartyRecovery()
-	core, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, afero.Afero{Fs: afero.NewMemMapFs()}, ""), recovery, zapLogger, nil, nil)
+	core, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, afero.Afero{Fs: afero.NewMemMapFs()}, "", zapLogger), recovery, zapLogger, nil, nil)
 	if err != nil {
 		panic(err)
 	}
@@ -281,8 +283,10 @@ func (c *Core) GetTLSMarbleRootCertificate(clientHello *tls.ClientHelloInfo) (*t
 // If reportData is not nil, a new quote is generated over the data and returned.
 func (c *Core) GetQuote(reportData []byte) ([]byte, error) {
 	if len(reportData) == 0 {
+		c.log.Debug("Returning cached quote")
 		return c.quote, nil
 	}
+	c.log.Debug("Generating new quote for report data")
 	quote, err := c.qi.Issue(reportData)
 	if err != nil && err.Error() != "OE_UNSUPPORTED" {
 		return nil, QuoteError{err}
@@ -308,6 +312,7 @@ func (c *Core) GenerateQuote(cert []byte) error {
 	}
 
 	c.quote = quote
+	c.log.Debug("Quote generated and stored")
 
 	return nil
 }
@@ -366,11 +371,13 @@ func (c *Core) GenerateSecrets(
 	for name, secret := range secrets {
 		// Skip user defined secrets, these will be uploaded by a user
 		if secret.UserDefined {
+			c.log.Debug("Skipping generation of user defined secret", zap.String("name", name))
 			continue
 		}
 
 		// Skip secrets from wrong context
 		if secret.Shared != (id == uuid.Nil) {
+			c.log.Debug("Skipping generation of secret", zap.String("name", name), zap.String("type", secret.Type), zap.Bool("shared", secret.Shared))
 			continue
 		}
 
@@ -425,7 +432,7 @@ func (c *Core) GenerateSecrets(
 
 		case manifest.SecretTypeCertED25519:
 			if secret.Size != 0 {
-				return nil, fmt.Errorf("invalid secret size for cert-ed25519, none is expected. given: %v", name)
+				return nil, fmt.Errorf("invalid secret size for cert-ed25519 secret %s: none is expected, got: %d", name, secret.Size)
 			}
 
 			// Generate keys
@@ -455,7 +462,7 @@ func (c *Core) GenerateSecrets(
 				curve = elliptic.P521()
 			default:
 				c.log.Error("ECDSA secrets only support P224, P256, P384 and P521 as curve. Check the supplied size.", zap.String("name", name), zap.String("type", secret.Type), zap.Uint("size", secret.Size))
-				return nil, fmt.Errorf("unsupported size %d: does not map to a supported curve", secret.Size)
+				return nil, fmt.Errorf("invalid secret size for cert-ecdsa secret %s: unsupported size %d: does not map to a supported curve", name, secret.Size)
 			}
 
 			// Generate keys
@@ -472,7 +479,7 @@ func (c *Core) GenerateSecrets(
 			}
 
 		default:
-			return nil, fmt.Errorf("unsupported secret of type %s", secret.Type)
+			return nil, fmt.Errorf("secret %s is invalid: unsupported secret of type %s", name, secret.Type)
 		}
 	}
 

coordinator/core/core_test.go

@@ -71,7 +71,7 @@ func TestSeal(t *testing.T) {
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
 
-	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 
 	// Set manifest. This will seal the state.
@@ -89,7 +89,7 @@ func TestSeal(t *testing.T) {
 	cSecrets := testutil.GetSecretMap(t, c.txHandle)
 
 	// Check sealing with a new core initialized with the sealed state.
-	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	clientAPI, err = clientapi.New(c2.txHandle, c2.recovery, c2, zapLogger)
 	require.NoError(err)
@@ -125,7 +125,7 @@ func TestRecover(t *testing.T) {
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
 
-	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	clientAPI, err := clientapi.New(c.txHandle, c.recovery, c, zapLogger)
 	require.NoError(err)
@@ -145,7 +145,7 @@ func TestRecover(t *testing.T) {
 
 	// Initialize new core and let unseal fail
 	sealer.UnsealError = &seal.EncryptionKeyError{}
-	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	sealer.UnsealError = nil
 	require.NoError(err)
 	clientAPI, err = clientapi.New(c2.txHandle, c2.recovery, c2, zapLogger)
@@ -304,14 +304,14 @@ func TestUnsetRestart(t *testing.T) {
 	recovery := recovery.NewSinglePartyRecovery()
 
 	// create a new core, this seals the state with only certificate and keys
-	c1, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c1, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	c1State := testutil.GetState(t, c1.txHandle)
 	assert.Equal(state.AcceptingManifest, c1State)
 	cCert := testutil.GetCertificate(t, c1.txHandle, constants.SKCoordinatorRootCert)
 
 	// create a second core, this should overwrite the previously sealed certificate and keys since no manifest was set
-	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	c2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	c2State := testutil.GetState(t, c2.txHandle)
 	assert.Equal(state.AcceptingManifest, c2State)

coordinator/core/marbleapi_test.go

@@ -59,7 +59,7 @@ func TestActivate(t *testing.T) {
 	sealer := &seal.MockSealer{}
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
-	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	require.NotNil(coreServer)
 
@@ -153,7 +153,7 @@ func TestMarbleSecretDerivation(t *testing.T) {
 	sealer := &seal.MockSealer{}
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
-	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	require.NotNil(coreServer)
 
@@ -584,7 +584,7 @@ func TestSecurityLevelUpdate(t *testing.T) {
 	sealer := &seal.MockSealer{}
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
-	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	require.NotNil(coreServer)
 
@@ -615,7 +615,7 @@ func TestSecurityLevelUpdate(t *testing.T) {
 	spawner.newMarble(t, "frontend", "Azure", uuid.New(), false)
 
 	// Use a new core and test if updated manifest persisted after restart
-	coreServer2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	coreServer2, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	coreServer2State := testutil.GetState(t, coreServer2.txHandle)
 	coreServer2UpdatedPkg := testutil.GetPackage(t, coreServer2.txHandle, "frontend")
@@ -691,7 +691,7 @@ func TestActivateWithMissingParameters(t *testing.T) {
 	sealer := &seal.MockSealer{}
 	fs := afero.NewMemMapFs()
 	recovery := recovery.NewSinglePartyRecovery()
-	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, nil, nil)
+	coreServer, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, nil, nil)
 	require.NoError(err)
 	require.NotNil(coreServer)
 
@@ -718,10 +718,11 @@ func TestActivateWithTTLSforMarbleWithoutEnvVars(t *testing.T) {
 	assert := assert.New(t)
 	require := require.New(t)
 
+	log := zaptest.NewLogger(t)
 	validator := quote.NewMockValidator()
 	issuer := quote.NewMockIssuer()
-	store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "")
-	coreServer, err := NewCore(nil, validator, issuer, store, recovery.NewSinglePartyRecovery(), zaptest.NewLogger(t), nil, nil)
+	store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", log)
+	coreServer, err := NewCore(nil, validator, issuer, store, recovery.NewSinglePartyRecovery(), log, nil, nil)
 	require.NoError(err)
 
 	clientAPI, err := clientapi.New(coreServer.txHandle, coreServer.recovery, coreServer, coreServer.log)

coordinator/core/metrics_test.go

@@ -47,7 +47,7 @@ func TestStoreWrapperMetrics(t *testing.T) {
 	//
 	reg := prometheus.NewRegistry()
 	fac := promauto.With(reg)
-	c, _ := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, &fac, nil)
+	c, _ := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, &fac, nil)
 	assert.Equal(1, promtest.CollectAndCount(c.metrics.coordinatorState))
 	assert.Equal(float64(state.AcceptingManifest), promtest.ToFloat64(c.metrics.coordinatorState))
 
@@ -64,7 +64,7 @@ func TestStoreWrapperMetrics(t *testing.T) {
 	reg = prometheus.NewRegistry()
 	fac = promauto.With(reg)
 	sealer.UnsealError = &seal.EncryptionKeyError{}
-	c, err = NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, ""), recovery, zapLogger, &fac, nil)
+	c, err = NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, fs, "", zapLogger), recovery, zapLogger, &fac, nil)
 	sealer.UnsealError = nil
 	require.NoError(err)
 	assert.Equal(1, promtest.CollectAndCount(c.metrics.coordinatorState))
@@ -98,7 +98,7 @@ func TestMarbleAPIMetrics(t *testing.T) {
 	recovery := recovery.NewSinglePartyRecovery()
 	promRegistry := prometheus.NewRegistry()
 	promFactory := promauto.With(promRegistry)
-	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, afero.NewMemMapFs(), ""), recovery, zapLogger, &promFactory, nil)
+	c, err := NewCore([]string{"localhost"}, validator, issuer, stdstore.New(sealer, afero.NewMemMapFs(), "", zapLogger), recovery, zapLogger, &promFactory, nil)
 	require.NoError(err)
 	require.NotNil(c)