diff --git a/CHANGELOG.md b/CHANGELOG.md index 90c9c3f2e0..b124d87c02 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ Improvements: +* Age verbose encryption and decryption logs now include the stored recipient. * Dependency updates ([#2178](https://github.com/getsops/sops/pull/2178)). * Make sure all files are formatted ([#2181](https://github.com/getsops/sops/pull/2181)). * The documentation for SOPS can now be found on [getsops.io](https://getsops.io) diff --git a/age/keysource.go b/age/keysource.go index 4eb9a200ed..080ef82678 100644 --- a/age/keysource.go +++ b/age/keysource.go @@ -164,7 +164,7 @@ func (key *MasterKey) Encrypt(dataKey []byte) error { if key.parsedRecipient == nil { parsedRecipient, err := parseRecipient(key.Recipient) if err != nil { - log.WithField("recipient", key.parsedRecipient).Info("Encryption failed") + log.WithField("recipient", key.Recipient).Info("Encryption failed") return err } key.parsedRecipient = parsedRecipient @@ -174,24 +174,24 @@ func (key *MasterKey) Encrypt(dataKey []byte) error { aw := armor.NewWriter(&buffer) w, err := age.Encrypt(aw, key.parsedRecipient) if err != nil { - log.WithField("recipient", key.parsedRecipient).Info("Encryption failed") + log.WithField("recipient", key.Recipient).Info("Encryption failed") return fmt.Errorf("failed to create writer for encrypting sops data key with age: %w", err) } if _, err := w.Write(dataKey); err != nil { - log.WithField("recipient", key.parsedRecipient).Info("Encryption failed") + log.WithField("recipient", key.Recipient).Info("Encryption failed") return fmt.Errorf("failed to encrypt sops data key with age: %w", err) } if err := w.Close(); err != nil { - log.WithField("recipient", key.parsedRecipient).Info("Encryption failed") + log.WithField("recipient", key.Recipient).Info("Encryption failed") return fmt.Errorf("failed to close writer for encrypting sops data key with age: %w", err) } if err := aw.Close(); err != nil { - log.WithField("recipient", key.parsedRecipient).Info("Encryption failed") + log.WithField("recipient", key.Recipient).Info("Encryption failed") return fmt.Errorf("failed to close armored writer: %w", err) } key.SetEncryptedDataKey(buffer.Bytes()) - log.WithField("recipient", key.parsedRecipient).Info("Encryption succeeded") + log.WithField("recipient", key.Recipient).Info("Encryption succeeded") return nil } @@ -247,7 +247,7 @@ func (key *MasterKey) Decrypt() ([]byte, error) { var ids ParsedIdentities ids, unusedLocations, errs = key.loadIdentities() if len(ids) == 0 { - log.Info("Decryption failed") + log.WithField("recipient", key.Recipient).Info("Decryption failed") return nil, formatError("failed to load age identities", nil, errs, unusedLocations) } ids.ApplyToMasterKey(key) @@ -257,17 +257,17 @@ func (key *MasterKey) Decrypt() ([]byte, error) { ar := armor.NewReader(src) r, err := age.Decrypt(ar, key.parsedIdentities...) if err != nil { - log.Info("Decryption failed") + log.WithField("recipient", key.Recipient).Info("Decryption failed") return nil, formatError("failed to create reader for decrypting sops data key with age", err, errs, unusedLocations) } var b bytes.Buffer if _, err := io.Copy(&b, r); err != nil { - log.Info("Decryption failed") + log.WithField("recipient", key.Recipient).Info("Decryption failed") return nil, fmt.Errorf("failed to copy age decrypted data into bytes.Buffer: %w", err) } - log.Info("Decryption succeeded") + log.WithField("recipient", key.Recipient).Info("Decryption succeeded") return b.Bytes(), nil } diff --git a/age/keysource_test.go b/age/keysource_test.go index da315d1a40..2ab2b00e9b 100644 --- a/age/keysource_test.go +++ b/age/keysource_test.go @@ -2,12 +2,15 @@ package age import ( "fmt" + "io" "os" "path/filepath" "runtime" "strings" "testing" + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" ) @@ -61,6 +64,27 @@ em9PWmRMMTY4aytYTnVZN04yeER5Z2E3TWxWT3JTZWR2ekUKp/HZLy4MzQqoszGk -----END AGE ENCRYPTED FILE-----` ) +func captureAgeLogs(t *testing.T) *test.Hook { + t.Helper() + + originalHooks := log.Hooks + originalLevel := log.GetLevel() + originalOutput := log.Out + + log.Hooks = make(logrus.LevelHooks) + hook := test.NewLocal(log) + log.SetLevel(logrus.InfoLevel) + log.SetOutput(io.Discard) + + t.Cleanup(func() { + log.Hooks = originalHooks + log.SetLevel(originalLevel) + log.SetOutput(originalOutput) + }) + + return hook +} + func TestMasterKeysFromRecipients(t *testing.T) { const otherRecipient = "age1tmaae3ld5vpevmsh5yacsauzx8jetg300mpvc4ugp5zr5l6ssq9sla97ep" @@ -179,6 +203,22 @@ func TestMasterKey_Encrypt(t *testing.T) { assert.NotEmpty(t, key.EncryptedKey) }) + t.Run("logs recipient on success", func(t *testing.T) { + key := &MasterKey{ + Recipient: mockRecipient, + } + hook := captureAgeLogs(t) + + assert.NoError(t, key.Encrypt([]byte(mockEncryptedKeyPlain))) + assert.NotEmpty(t, key.EncryptedKey) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Encryption succeeded", entries[0].Message) + assert.Equal(t, mockRecipient, entries[0].Data["recipient"]) + } + }) + t.Run("recipient ssh", func(t *testing.T) { key := &MasterKey{ Recipient: mockSshRecipient, @@ -187,6 +227,22 @@ func TestMasterKey_Encrypt(t *testing.T) { assert.NotEmpty(t, key.EncryptedKey) }) + t.Run("logs ssh recipient on success", func(t *testing.T) { + key := &MasterKey{ + Recipient: mockSshRecipient, + } + hook := captureAgeLogs(t) + + assert.NoError(t, key.Encrypt([]byte(mockEncryptedKeyPlain))) + assert.NotEmpty(t, key.EncryptedKey) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Encryption succeeded", entries[0].Message) + assert.Equal(t, mockSshRecipient, entries[0].Data["recipient"]) + } + }) + t.Run("parsed recipient", func(t *testing.T) { key := &MasterKey{ parsedRecipient: mockParsedRecipient, @@ -213,6 +269,24 @@ func TestMasterKey_Encrypt(t *testing.T) { assert.Empty(t, key.EncryptedKey) }) + t.Run("logs recipient on invalid recipient failure", func(t *testing.T) { + key := &MasterKey{ + Recipient: "invalid", + } + hook := captureAgeLogs(t) + + err := key.Encrypt([]byte(mockEncryptedKeyPlain)) + assert.Error(t, err) + assert.ErrorContains(t, err, "failed to parse input, unknown recipient type:") + assert.Empty(t, key.EncryptedKey) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Encryption failed", entries[0].Message) + assert.Equal(t, "invalid", entries[0].Data["recipient"]) + } + }) + t.Run("parsed recipient and invalid recipient", func(t *testing.T) { key := &MasterKey{ Recipient: "invalid", @@ -254,6 +328,81 @@ func TestMasterKey_Decrypt(t *testing.T) { assert.EqualValues(t, mockEncryptedKeyPlain, got) }) + t.Run("logs recipient on success", func(t *testing.T) { + key := &MasterKey{EncryptedKey: mockEncryptedKey, Recipient: mockRecipient} + var ids ParsedIdentities + assert.NoError(t, ids.Import(mockIdentity)) + ids.ApplyToMasterKey(key) + hook := captureAgeLogs(t) + + got, err := key.Decrypt() + assert.NoError(t, err) + assert.EqualValues(t, mockEncryptedKeyPlain, got) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Decryption succeeded", entries[0].Message) + assert.Equal(t, mockRecipient, entries[0].Data["recipient"]) + } + }) + + t.Run("logs ssh recipient on success", func(t *testing.T) { + identity, err := parseSSHIdentityFromPrivateKeyCmdOutput([]byte(mockSshIdentity)) + assert.NoError(t, err) + key := &MasterKey{ + EncryptedKey: mockEncryptedSshKey, + Recipient: mockSshRecipient, + parsedIdentities: ParsedIdentities{identity}, + } + hook := captureAgeLogs(t) + + got, err := key.Decrypt() + assert.NoError(t, err) + assert.EqualValues(t, mockEncryptedKeyPlain, got) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Decryption succeeded", entries[0].Message) + assert.Equal(t, mockSshRecipient, entries[0].Data["recipient"]) + } + }) + + t.Run("logs recipient on failure", func(t *testing.T) { + key := &MasterKey{EncryptedKey: "invalid", Recipient: mockRecipient} + var ids ParsedIdentities + assert.NoError(t, ids.Import(mockIdentity)) + ids.ApplyToMasterKey(key) + hook := captureAgeLogs(t) + + got, err := key.Decrypt() + assert.Error(t, err) + assert.ErrorContains(t, err, "failed to create reader for decrypting sops data key with age") + assert.Nil(t, got) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Decryption failed", entries[0].Message) + assert.Equal(t, mockRecipient, entries[0].Data["recipient"]) + } + }) + + t.Run("logs recipient on identity load failure", func(t *testing.T) { + overwriteUserConfigDir(t, t.TempDir()) + key := &MasterKey{EncryptedKey: mockEncryptedKey, Recipient: mockRecipient} + hook := captureAgeLogs(t) + + got, err := key.Decrypt() + assert.Error(t, err) + assert.ErrorContains(t, err, "failed to load age identities") + assert.Nil(t, got) + + entries := hook.AllEntries() + if assert.Len(t, entries, 1) { + assert.Equal(t, "Decryption failed", entries[0].Message) + assert.Equal(t, mockRecipient, entries[0].Data["recipient"]) + } + }) + t.Run("loaded identities", func(t *testing.T) { overwriteUserConfigDir(t, t.TempDir()) key := &MasterKey{EncryptedKey: mockEncryptedKey} @@ -577,9 +726,35 @@ func TestMasterKey_loadIdentities(t *testing.T) { }) } +func clearAgeIdentityEnv(t *testing.T) { + t.Helper() + + for _, name := range []string{ + SopsAgeKeyEnv, + SopsAgeKeyFileEnv, + SopsAgeKeyCmdEnv, + SopsAgeSshPrivateKeyCmdEnv, + SopsAgeSshPrivateKeyFileEnv, + } { + name := name + value, ok := os.LookupEnv(name) + assert.NoError(t, os.Unsetenv(name)) + t.Cleanup(func() { + if ok { + assert.NoError(t, os.Setenv(name, value)) + } else { + assert.NoError(t, os.Unsetenv(name)) + } + }) + } +} + // overwriteUserConfigDir sets the user config directory and the user home directory -// based on the os.UserConfigDir logic. +// based on the os.UserConfigDir logic. It also clears AGE identity environment +// variables so tests only load identities from sources they explicitly set. func overwriteUserConfigDir(t *testing.T, path string) { + clearAgeIdentityEnv(t) + switch runtime.GOOS { case "windows": t.Setenv("AppData", path) @@ -607,10 +782,12 @@ func TestUserConfigDir(t *testing.T) { func TestMasterKey_Identities_Passphrase(t *testing.T) { t.Run(SopsAgeKeyEnv, func(t *testing.T) { + overwriteUserConfigDir(t, t.TempDir()) key := &MasterKey{EncryptedKey: mockEncryptedKey} t.Setenv(SopsAgeKeyEnv, mockEncryptedIdentity) - //blocks calling gpg-agent + // blocks calling gpg-agent so tests use testOnlyAgePassword os.Unsetenv("XDG_RUNTIME_DIR") + t.Setenv("GPG_AGENT_INFO", "") testOnlyAgePassword = mockIdentityPassphrase got, err := key.Decrypt() testOnlyAgePassword = "" @@ -629,8 +806,9 @@ func TestMasterKey_Identities_Passphrase(t *testing.T) { key := &MasterKey{EncryptedKey: mockEncryptedKey} t.Setenv(SopsAgeKeyFileEnv, keyPath) - //blocks calling gpg-agent + // blocks calling gpg-agent so tests use testOnlyAgePassword os.Unsetenv("XDG_RUNTIME_DIR") + t.Setenv("GPG_AGENT_INFO", "") testOnlyAgePassword = mockIdentityPassphrase got, err := key.Decrypt() @@ -641,10 +819,12 @@ func TestMasterKey_Identities_Passphrase(t *testing.T) { }) t.Run("invalid encrypted key", func(t *testing.T) { + overwriteUserConfigDir(t, t.TempDir()) key := &MasterKey{EncryptedKey: "invalid"} t.Setenv(SopsAgeKeyEnv, mockEncryptedIdentity) - //blocks calling gpg-agent + // blocks calling gpg-agent so tests use testOnlyAgePassword os.Unsetenv("XDG_RUNTIME_DIR") + t.Setenv("GPG_AGENT_INFO", "") testOnlyAgePassword = mockIdentityPassphrase got, err := key.Decrypt()