diff --git a/cmd/coordinator/enclavemain.go b/cmd/coordinator/enclavemain.go index 6299b0cb..3c7e6a93 100644 --- a/cmd/coordinator/enclavemain.go +++ b/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) } diff --git a/cmd/coordinator/main.go b/cmd/coordinator/main.go index a830aed8..1a33c82a 100644 --- a/cmd/coordinator/main.go +++ b/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) } diff --git a/cmd/coordinator/run.go b/cmd/coordinator/run.go index 29c03f5e..c89f9ad0 100644 --- a/cmd/coordinator/run.go +++ b/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") diff --git a/coordinator/clientapi/clientapi_test.go b/coordinator/clientapi/clientapi_test.go index 4a789bfe..0a0a05a0 100644 --- a/coordinator/clientapi/clientapi_test.go +++ b/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,7 +186,7 @@ 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 @@ -194,7 +194,7 @@ func TestGetManifestSignature(t *testing.T) { }, "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 }(), @@ -202,7 +202,7 @@ func TestGetManifestSignature(t *testing.T) { }, "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{ diff --git a/coordinator/clientapi/legacy_test.go b/coordinator/clientapi/legacy_test.go index 4f41b516..d42ad1bb 100644 --- a/coordinator/clientapi/legacy_test.go +++ b/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) diff --git a/coordinator/constants/constants.go b/coordinator/constants/constants.go index 141b6583..4dbba1fc 100644 --- a/coordinator/constants/constants.go +++ b/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" ) diff --git a/coordinator/core/certificate_test.go b/coordinator/core/certificate_test.go index 4320bd81..c97bb2d4 100644 --- a/coordinator/core/certificate_test.go +++ b/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) diff --git a/coordinator/core/core.go b/coordinator/core/core.go index 9ce52cb1..fc369478 100644 --- a/coordinator/core/core.go +++ b/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) } } diff --git a/coordinator/core/core_test.go b/coordinator/core/core_test.go index fe18a4a3..53fbe2d2 100644 --- a/coordinator/core/core_test.go +++ b/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) diff --git a/coordinator/core/marbleapi_test.go b/coordinator/core/marbleapi_test.go index 8d2f4a1f..12fcbbb5 100644 --- a/coordinator/core/marbleapi_test.go +++ b/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) diff --git a/coordinator/core/metrics_test.go b/coordinator/core/metrics_test.go index f55d92da..a52826ac 100644 --- a/coordinator/core/metrics_test.go +++ b/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) diff --git a/coordinator/seal/noenclavesealer.go b/coordinator/seal/noenclavesealer.go index 3a3ccd50..16aee2a5 100644 --- a/coordinator/seal/noenclavesealer.go +++ b/coordinator/seal/noenclavesealer.go @@ -10,22 +10,26 @@ import ( "fmt" "github.com/edgelesssys/ego/ecrypto" + "go.uber.org/zap" ) // NoEnclaveSealer is a sealer for a -noenclave instance and performs encryption with a fixed key. type NoEnclaveSealer struct { encryptionKey []byte + log *zap.Logger } // NewNoEnclaveSealer creates and initializes a new NoEnclaveSealer object. -func NewNoEnclaveSealer() *NoEnclaveSealer { - return &NoEnclaveSealer{} +func NewNoEnclaveSealer(log *zap.Logger) *NoEnclaveSealer { + return &NoEnclaveSealer{ + log: log, + } } // Unseal decrypts sealedData and returns the decrypted data, // as well as the prefixed unencrypted metadata of the cipher text. func (s *NoEnclaveSealer) Unseal(sealedData []byte) ([]byte, []byte, error) { - unencryptedData, cipherText, err := prepareCipherText(sealedData) + unencryptedData, cipherText, err := prepareCipherText(sealedData, s.log) if err != nil { return unencryptedData, nil, err } @@ -45,7 +49,7 @@ func (s *NoEnclaveSealer) Unseal(sealedData []byte) ([]byte, []byte, error) { // Seal encrypts the given data using the sealer's key. func (s *NoEnclaveSealer) Seal(unencryptedData []byte, toBeEncrypted []byte) ([]byte, error) { - return sealData(unencryptedData, toBeEncrypted, s.encryptionKey) + return sealData(unencryptedData, toBeEncrypted, s.encryptionKey, s.log) } // SealEncryptionKey implements the Sealer interface. diff --git a/coordinator/seal/seal.go b/coordinator/seal/seal.go index b5d6dde8..b1e21ba8 100644 --- a/coordinator/seal/seal.go +++ b/coordinator/seal/seal.go @@ -14,6 +14,7 @@ import ( "fmt" "github.com/edgelesssys/ego/ecrypto" + "go.uber.org/zap" ) // EncryptionKeyError occurs if the encryption key cannot be unsealed. @@ -49,17 +50,20 @@ type Sealer interface { // AESGCMSealer implements the Sealer interface using AES-GCM for confidentiality and authentication. type AESGCMSealer struct { encryptionKey []byte + log *zap.Logger } // NewAESGCMSealer creates and initializes a new AESGCMSealer object. -func NewAESGCMSealer() *AESGCMSealer { - return &AESGCMSealer{} +func NewAESGCMSealer(log *zap.Logger) *AESGCMSealer { + return &AESGCMSealer{ + log: log, + } } // Unseal decrypts sealedData and returns the decrypted data, // as well as the prefixed unencrypted metadata of the cipher text. func (s *AESGCMSealer) Unseal(sealedData []byte) ([]byte, []byte, error) { - unencryptedData, cipherText, err := prepareCipherText(sealedData) + unencryptedData, cipherText, err := prepareCipherText(sealedData, s.log) if err != nil { return unencryptedData, nil, err } @@ -79,15 +83,17 @@ func (s *AESGCMSealer) Unseal(sealedData []byte) ([]byte, []byte, error) { // Seal encrypts and stores information to the fs. func (s *AESGCMSealer) Seal(unencryptedData []byte, toBeEncrypted []byte) ([]byte, error) { - return sealData(unencryptedData, toBeEncrypted, s.encryptionKey) + return sealData(unencryptedData, toBeEncrypted, s.encryptionKey, s.log) } // SealEncryptionKey seals an encryption key with the selected enclave key. func (s *AESGCMSealer) SealEncryptionKey(encryptionKey []byte, mode Mode) ([]byte, error) { switch mode { case ModeProductKey: + s.log.Debug("Sealing encryption key with product key") return ecrypto.SealWithProductKey(encryptionKey, nil) case ModeUniqueKey: + s.log.Debug("Sealing encryption key with unique key") return ecrypto.SealWithUniqueKey(encryptionKey, nil) } return nil, errors.New("sealing is disabled") @@ -123,13 +129,15 @@ func GenerateEncryptionKey() ([]byte, error) { // prepareCipherText validates format of the given sealed data. // It returns the unencrypted metadata and the cipher text. -func prepareCipherText(sealedData []byte) (unencryptedData []byte, cipherText []byte, err error) { +func prepareCipherText(sealedData []byte, log *zap.Logger) (unencryptedData []byte, cipherText []byte, err error) { + log.Debug("Preparing cipher text for unsealing", zap.Int("sealedDataLength", len(sealedData))) if len(sealedData) <= 4 { return nil, nil, errors.New("sealed state is missing data") } // Retrieve recovery secret hash map encodedUnencryptedDataLength := binary.LittleEndian.Uint32(sealedData[:4]) + log.Debug("Checking encoded unencrypted data", zap.Uint32("length", encodedUnencryptedDataLength)) // Check if we do not go out of bounds if 4+encodedUnencryptedDataLength > uint32(len(sealedData)) { @@ -140,6 +148,7 @@ func prepareCipherText(sealedData []byte) (unencryptedData []byte, cipherText [] unencryptedData = sealedData[4 : 4+encodedUnencryptedDataLength] } cipherText = sealedData[4+encodedUnencryptedDataLength:] + log.Debug("Cipher text is ready for unsealing", zap.Binary("unencryptedData", unencryptedData)) return unencryptedData, cipherText, nil } @@ -148,7 +157,8 @@ func prepareCipherText(sealedData []byte) (unencryptedData []byte, cipherText [] // It returns the encrypted data prefixed with the unencrypted data and it's length. // // Format: uint32(littleEndian(len(unencryptedData))) || unencryptedData || encrypt(toBeEncrypted). -func sealData(unencryptedData, toBeEncrypted, encryptionKey []byte) ([]byte, error) { +func sealData(unencryptedData, toBeEncrypted, encryptionKey []byte, log *zap.Logger) ([]byte, error) { + log.Debug("Preparing to seal data", zap.Binary("unencryptedData", unencryptedData)) if encryptionKey == nil { return nil, fmt.Errorf("encrypting data: %w", ErrMissingEncryptionKey) } @@ -166,5 +176,6 @@ func sealData(unencryptedData, toBeEncrypted, encryptionKey []byte) ([]byte, err // Append unencrypted data with encrypted data encryptedData = append(unencryptedData, encryptedData...) + log.Debug("Data sealing completed") return encryptedData, nil } diff --git a/coordinator/seal/seal_test.go b/coordinator/seal/seal_test.go index db9902cb..f4e55468 100644 --- a/coordinator/seal/seal_test.go +++ b/coordinator/seal/seal_test.go @@ -12,6 +12,7 @@ import ( "testing" "github.com/stretchr/testify/assert" + "go.uber.org/zap/zaptest" ) func TestPrepareCipherText(t *testing.T) { @@ -66,7 +67,7 @@ func TestPrepareCipherText(t *testing.T) { t.Run(name, func(t *testing.T) { assert := assert.New(t) - _, _, err := prepareCipherText(tc.sealedData) + _, _, err := prepareCipherText(tc.sealedData, zaptest.NewLogger(t)) if tc.wantErr { assert.Error(err) } else { @@ -118,7 +119,7 @@ func TestSealUnseal(t *testing.T) { for name, tc := range testCases { t.Run(name, func(t *testing.T) { assert := assert.New(t) - sealer := NewAESGCMSealer() + sealer := NewAESGCMSealer(zaptest.NewLogger(t)) sealer.encryptionKey = tc.encryptionKey sealedData, err := sealer.Seal(tc.metadata, tc.data) diff --git a/coordinator/server/metrics_test.go b/coordinator/server/metrics_test.go index f46a9c21..a8ee9f76 100644 --- a/coordinator/server/metrics_test.go +++ b/coordinator/server/metrics_test.go @@ -92,7 +92,7 @@ func newTestClientAPI(t *testing.T) *clientapi.ClientAPI { validator := quote.NewMockValidator() issuer := quote.NewMockIssuer() - store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", log) recovery := recovery.NewSinglePartyRecovery() core, err := core.NewCore([]string{"localhost"}, validator, issuer, store, recovery, log, nil, nil) require.NoError(err) diff --git a/coordinator/store/stdstore/stdstore.go b/coordinator/store/stdstore/stdstore.go index e8842dfc..ba6c01d5 100644 --- a/coordinator/store/stdstore/stdstore.go +++ b/coordinator/store/stdstore/stdstore.go @@ -19,6 +19,7 @@ import ( "github.com/edgelesssys/marblerun/coordinator/seal" "github.com/edgelesssys/marblerun/coordinator/store" "github.com/spf13/afero" + "go.uber.org/zap" ) const ( @@ -40,15 +41,18 @@ type StdStore struct { recoveryData []byte recoveryMode bool sealDir string + + log *zap.Logger } // New creates and initializes a new StdStore object. -func New(sealer seal.Sealer, fs afero.Fs, sealDir string) *StdStore { +func New(sealer seal.Sealer, fs afero.Fs, sealDir string, log *zap.Logger) *StdStore { s := &StdStore{ data: make(map[string][]byte), sealer: sealer, fs: afero.Afero{Fs: fs}, sealDir: sealDir, + log: log, } return s @@ -57,6 +61,7 @@ func New(sealer seal.Sealer, fs afero.Fs, sealDir string) *StdStore { // Get retrieves a value from StdStore by Type and Name. func (s *StdStore) Get(request string) ([]byte, error) { s.mux.Lock() + s.log.Debug("Retrieving value from store", zap.String("request", request)) value, ok := s.data[request] s.mux.Unlock() @@ -68,6 +73,7 @@ func (s *StdStore) Get(request string) ([]byte, error) { // Put saves a value in StdStore by Type and Name. func (s *StdStore) Put(request string, requestData []byte) error { + s.log.Debug("Saving value to store", zap.String("request", request)) tx := s.beginTransaction() defer tx.Rollback() if err := tx.Put(request, requestData); err != nil { @@ -78,6 +84,7 @@ func (s *StdStore) Put(request string, requestData []byte) error { // Delete removes a value from StdStore. func (s *StdStore) Delete(request string) error { + s.log.Debug("Deleting value from store", zap.String("request", request)) tx := s.beginTransaction() defer tx.Rollback() if err := tx.Delete(request); err != nil { @@ -110,39 +117,51 @@ func (s *StdStore) LoadState() ([]byte, error) { defer s.mux.Unlock() // load from fs + s.log.Debug("Loading sealed state from file system", zap.String("filename", filepath.Join(s.sealDir, SealedDataFname))) sealedData, err := s.fs.ReadFile(filepath.Join(s.sealDir, SealedDataFname)) if errors.Is(err, afero.ErrFileNotFound) { // No sealed data found, back up any existing seal keys + s.log.Debug("No sealed data found, backing up existing seal keys") s.backupEncryptionKey() return nil, nil } else if err != nil { + s.log.Debug("Error reading sealed data", zap.Error(err)) return nil, err } + s.log.Debug("Unsealing loaded state") encodedRecoveryData, stateRaw, err := s.sealer.Unseal(sealedData) if err != nil { + s.log.Debug("Unsealing state failed", zap.Error(err)) if !errors.Is(err, seal.ErrMissingEncryptionKey) { + s.log.Debug("No encryption key found, entering recovery mode") s.recoveryMode = true return encodedRecoveryData, fmt.Errorf("unsealing state: %w", err) } // Try to unseal encryption key from disk using product key // And retry unsealing the sealed data + s.log.Debug("Trying to unseal encryption key") if err := s.unsealEncryptionKey(); err != nil { + s.log.Debug("Unsealing encryption key failed, entering recovery mode", zap.Error(err)) s.recoveryMode = true return encodedRecoveryData, &seal.EncryptionKeyError{Err: err} } + s.log.Debug("Retrying unsealing state") encodedRecoveryData, stateRaw, err = s.sealer.Unseal(sealedData) if err != nil { + s.log.Debug("Unsealing state failed, entering recovery mode", zap.Error(err)) s.recoveryMode = true return encodedRecoveryData, fmt.Errorf("retry unsealing state with loaded key: %w", err) } } if len(stateRaw) == 0 { + s.log.Debug("State is empty, nothing to do") return encodedRecoveryData, nil } // load state + s.log.Debug("Loading state from unsealed JSON blob") var loadedData map[string][]byte if err := json.Unmarshal(stateRaw, &loadedData); err != nil { return encodedRecoveryData, err @@ -154,22 +173,26 @@ func (s *StdStore) LoadState() ([]byte, error) { // SetRecoveryData sets the recovery data that is added to the sealed data. func (s *StdStore) SetRecoveryData(recoveryData []byte) { + s.log.Debug("Setting recovery data and removing recovery mode", zap.ByteString("recoveryData", recoveryData)) s.recoveryData = recoveryData s.recoveryMode = false } // SetEncryptionKey sets the encryption key for sealing and unsealing. func (s *StdStore) SetEncryptionKey(encryptionKey []byte, mode seal.Mode) error { + s.log.Debug("Setting encryption key", zap.Int("mode", int(mode))) if mode != seal.ModeDisabled { // If there already is an existing key file stored on disk, save it s.backupEncryptionKey() + s.log.Debug("Sealing state encryption key") encryptedKey, err := s.sealer.SealEncryptionKey(encryptionKey, mode) if err != nil { return fmt.Errorf("encrypting data key: %w", err) } // Write the sealed encryption key to disk + s.log.Debug("Writing sealed encryption key to disk", zap.String("filename", filepath.Join(s.sealDir, SealedKeyFname))) if err = s.fs.WriteFile(filepath.Join(s.sealDir, SealedKeyFname), encryptedKey, 0o600); err != nil { return fmt.Errorf("writing encrypted key to disk: %w", err) } @@ -182,7 +205,8 @@ func (s *StdStore) SetEncryptionKey(encryptionKey []byte, mode seal.Mode) error } func (s *StdStore) beginTransaction() *StdTransaction { - tx := StdTransaction{store: s, data: map[string][]byte{}} + s.log.Debug("Starting new store transaction") + tx := StdTransaction{store: s, data: map[string][]byte{}, log: s.log} s.txmux.Lock() s.mux.Lock() @@ -196,6 +220,7 @@ func (s *StdStore) beginTransaction() *StdTransaction { // commit saves the store's data to disk. func (s *StdStore) commit(data map[string][]byte) error { + s.log.Debug("Committing store transaction", zap.Bool("recoveryMode", s.recoveryMode), zap.Int("sealMode", int(s.sealMode))) dataRaw, err := json.Marshal(data) if err != nil { return err @@ -204,12 +229,14 @@ func (s *StdStore) commit(data map[string][]byte) error { s.mux.Lock() defer s.mux.Unlock() if !s.recoveryMode && s.sealMode != seal.ModeDisabled { + s.log.Debug("Sealing transaction data") sealedData, err := s.sealer.Seal(s.recoveryData, dataRaw) if err != nil { return err } // atomically replace the sealed data file + s.log.Debug("Writing sealed transaction data to disk", zap.String("filename", filepath.Join(s.sealDir, SealedDataFname))) sealedDataPath := filepath.Join(s.sealDir, SealedDataFname) sealedDataPathTmp := sealedDataPath + ".tmp" if err := s.fs.WriteFile(sealedDataPathTmp, sealedData, 0o600); err != nil { @@ -221,6 +248,7 @@ func (s *StdStore) commit(data map[string][]byte) error { } s.data = data + s.log.Debug("Transaction committed") s.txmux.Unlock() return nil @@ -228,6 +256,7 @@ func (s *StdStore) commit(data map[string][]byte) error { // unsealEncryptionKey sets the seal key for the store's sealer by loading the encrypted key from disk. func (s *StdStore) unsealEncryptionKey() error { + s.log.Debug("Loading sealed encryption key from disk", zap.String("filename", filepath.Join(s.sealDir, SealedKeyFname))) encryptedKey, err := s.fs.ReadFile(filepath.Join(s.sealDir, SealedKeyFname)) if err != nil { return fmt.Errorf("reading encrypted key from disk: %w", err) @@ -245,6 +274,7 @@ func (s *StdStore) backupEncryptionKey() { if sealedKeyData, err := s.fs.ReadFile(filepath.Join(s.sealDir, SealedKeyFname)); err == nil { t := time.Now() newFileName := filepath.Join(s.sealDir, SealedKeyFname) + "_" + t.Format("20060102150405") + ".bak" + s.log.Debug("Creating backup of existing seal key", zap.String("filename", newFileName)) _ = s.fs.WriteFile(newFileName, sealedKeyData, 0o600) } } @@ -253,10 +283,12 @@ func (s *StdStore) backupEncryptionKey() { type StdTransaction struct { store *StdStore data map[string][]byte + log *zap.Logger } // Get retrieves a value. func (t *StdTransaction) Get(request string) ([]byte, error) { + t.log.Debug("Retrieving value from transaction", zap.String("request", request)) if value, ok := t.data[request]; ok { return value, nil } @@ -265,12 +297,14 @@ func (t *StdTransaction) Get(request string) ([]byte, error) { // Put saves a value. func (t *StdTransaction) Put(request string, requestData []byte) error { + t.log.Debug("Saving value to transaction", zap.String("request", request)) t.data[request] = requestData return nil } // Delete removes a value. func (t *StdTransaction) Delete(request string) error { + t.log.Debug("Deleting value from transaction", zap.String("request", request)) delete(t.data, request) return nil } @@ -298,6 +332,7 @@ func (t *StdTransaction) Commit(_ context.Context) error { // Rollback aborts a transaction. func (t *StdTransaction) Rollback() { + t.log.Debug("Rolling back transaction") if t.store != nil { t.store.txmux.Unlock() } diff --git a/coordinator/store/stdstore/stdstore_test.go b/coordinator/store/stdstore/stdstore_test.go index 180d0222..1a9d3973 100644 --- a/coordinator/store/stdstore/stdstore_test.go +++ b/coordinator/store/stdstore/stdstore_test.go @@ -15,13 +15,14 @@ import ( "github.com/spf13/afero" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "go.uber.org/zap/zaptest" ) func TestStdStore(t *testing.T) { assert := assert.New(t) ctx := context.Background() - str := New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + str := New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) _, err := str.LoadState() assert.NoError(err) @@ -56,7 +57,7 @@ func TestStdIterator(t *testing.T) { assert := assert.New(t) sealer := &seal.MockSealer{} - store := New(sealer, afero.NewMemMapFs(), "") + store := New(sealer, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) store.data = map[string][]byte{ "test:1": {0x00, 0x11}, "test:2": {0x00, 0x11}, @@ -123,7 +124,7 @@ func TestStdStoreSealing(t *testing.T) { fs := afero.NewMemMapFs() sealer := &seal.MockSealer{} - store := New(sealer, fs, "") + store := New(sealer, fs, "", zaptest.NewLogger(t)) _, err := store.LoadState() require.NoError(err) @@ -133,7 +134,7 @@ func TestStdStoreSealing(t *testing.T) { require.NoError(store.Put("test:input", testData1)) // Check sealing with a new store initialized with the sealed state - store2 := New(sealer, fs, "") + store2 := New(sealer, fs, "", zaptest.NewLogger(t)) _, err = store2.LoadState() require.NoError(err) val, err := store2.Get("test:input") @@ -152,7 +153,7 @@ func TestStdStoreRollback(t *testing.T) { assert := assert.New(t) ctx := context.Background() - store := New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + store := New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) _, err := store.LoadState() assert.NoError(err) @@ -199,7 +200,7 @@ func TestStdStoreRollback(t *testing.T) { func TestStdStoreDelete(t *testing.T) { assert := assert.New(t) - str := New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + str := New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) inputName := "test:input" inputData := []byte("test data") diff --git a/coordinator/store/wrapper/wrapper_test.go b/coordinator/store/wrapper/wrapper_test.go index b197f118..530ad9ff 100644 --- a/coordinator/store/wrapper/wrapper_test.go +++ b/coordinator/store/wrapper/wrapper_test.go @@ -23,6 +23,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/goleak" + "go.uber.org/zap/zaptest" ) func TestMain(m *testing.M) { @@ -34,7 +35,7 @@ func TestStoreWrapper(t *testing.T) { require := require.New(t) ctx := context.Background() - store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + store := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) rawManifest := []byte(test.ManifestJSON) curState := state.AcceptingManifest testSecret := manifest.Secret{ @@ -87,7 +88,7 @@ func TestStoreWrapperRollback(t *testing.T) { require := require.New(t) ctx := context.Background() - stor := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "") + stor := stdstore.New(&seal.MockSealer{}, afero.NewMemMapFs(), "", zaptest.NewLogger(t)) data := New(stor) startingState := state.AcceptingManifest diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 1f9f33d7..982fc404 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -23,10 +23,16 @@ func New() (*zap.Logger, error) { cfg = zap.NewProductionConfig() cfg.DisableStacktrace = true // Disable stacktraces in production } + + if util.Getenv(constants.DebugLogging, constants.DebugLoggingDefault) == "1" { + cfg.Level = zap.NewAtomicLevelAt(zap.DebugLevel) + } + log, err := cfg.Build() if err != nil { return nil, err } + log.Debug("Debug logging enabled") return log, nil }