Skip to content

Commit fe02407

Browse files
olomixolomix
committed
feat: include age recipient in decrypt logs
Signed-off-by: Oleg Lomaka <oleg.lomaka@gmail.com>
1 parent 57ce469 commit fe02407

3 files changed

Lines changed: 195 additions & 14 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44

55
Improvements:
66

7+
* Age verbose encryption and decryption logs now include the stored recipient.
78
* Dependency updates ([#2178](https://github.com/getsops/sops/pull/2178)).
89
* Make sure all files are formatted ([#2181](https://github.com/getsops/sops/pull/2181)).
910
* The documentation for SOPS can now be found on [getsops.io](https://getsops.io)

‎age/keysource.go‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -164,7 +164,7 @@ func (key *MasterKey) Encrypt(dataKey []byte) error {
164164
if key.parsedRecipient == nil {
165165
parsedRecipient, err := parseRecipient(key.Recipient)
166166
if err != nil {
167-
log.WithField("recipient", key.parsedRecipient).Info("Encryption failed")
167+
log.WithField("recipient", key.Recipient).Info("Encryption failed")
168168
return err
169169
}
170170
key.parsedRecipient = parsedRecipient
@@ -174,24 +174,24 @@ func (key *MasterKey) Encrypt(dataKey []byte) error {
174174
aw := armor.NewWriter(&buffer)
175175
w, err := age.Encrypt(aw, key.parsedRecipient)
176176
if err != nil {
177-
log.WithField("recipient", key.parsedRecipient).Info("Encryption failed")
177+
log.WithField("recipient", key.Recipient).Info("Encryption failed")
178178
return fmt.Errorf("failed to create writer for encrypting sops data key with age: %w", err)
179179
}
180180
if _, err := w.Write(dataKey); err != nil {
181-
log.WithField("recipient", key.parsedRecipient).Info("Encryption failed")
181+
log.WithField("recipient", key.Recipient).Info("Encryption failed")
182182
return fmt.Errorf("failed to encrypt sops data key with age: %w", err)
183183
}
184184
if err := w.Close(); err != nil {
185-
log.WithField("recipient", key.parsedRecipient).Info("Encryption failed")
185+
log.WithField("recipient", key.Recipient).Info("Encryption failed")
186186
return fmt.Errorf("failed to close writer for encrypting sops data key with age: %w", err)
187187
}
188188
if err := aw.Close(); err != nil {
189-
log.WithField("recipient", key.parsedRecipient).Info("Encryption failed")
189+
log.WithField("recipient", key.Recipient).Info("Encryption failed")
190190
return fmt.Errorf("failed to close armored writer: %w", err)
191191
}
192192

193193
key.SetEncryptedDataKey(buffer.Bytes())
194-
log.WithField("recipient", key.parsedRecipient).Info("Encryption succeeded")
194+
log.WithField("recipient", key.Recipient).Info("Encryption succeeded")
195195
return nil
196196
}
197197

@@ -247,7 +247,7 @@ func (key *MasterKey) Decrypt() ([]byte, error) {
247247
var ids ParsedIdentities
248248
ids, unusedLocations, errs = key.loadIdentities()
249249
if len(ids) == 0 {
250-
log.Info("Decryption failed")
250+
log.WithField("recipient", key.Recipient).Info("Decryption failed")
251251
return nil, formatError("failed to load age identities", nil, errs, unusedLocations)
252252
}
253253
ids.ApplyToMasterKey(key)
@@ -257,17 +257,17 @@ func (key *MasterKey) Decrypt() ([]byte, error) {
257257
ar := armor.NewReader(src)
258258
r, err := age.Decrypt(ar, key.parsedIdentities...)
259259
if err != nil {
260-
log.Info("Decryption failed")
260+
log.WithField("recipient", key.Recipient).Info("Decryption failed")
261261
return nil, formatError("failed to create reader for decrypting sops data key with age", err, errs, unusedLocations)
262262
}
263263

264264
var b bytes.Buffer
265265
if _, err := io.Copy(&b, r); err != nil {
266-
log.Info("Decryption failed")
266+
log.WithField("recipient", key.Recipient).Info("Decryption failed")
267267
return nil, fmt.Errorf("failed to copy age decrypted data into bytes.Buffer: %w", err)
268268
}
269269

270-
log.Info("Decryption succeeded")
270+
log.WithField("recipient", key.Recipient).Info("Decryption succeeded")
271271
return b.Bytes(), nil
272272
}
273273

‎age/keysource_test.go‎

Lines changed: 184 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2,12 +2,15 @@ package age
22

33
import (
44
"fmt"
5+
"io"
56
"os"
67
"path/filepath"
78
"runtime"
89
"strings"
910
"testing"
1011

12+
"github.com/sirupsen/logrus"
13+
"github.com/sirupsen/logrus/hooks/test"
1114
"github.com/stretchr/testify/assert"
1215
)
1316

@@ -61,6 +64,27 @@ em9PWmRMMTY4aytYTnVZN04yeER5Z2E3TWxWT3JTZWR2ekUKp/HZLy4MzQqoszGk
6164
-----END AGE ENCRYPTED FILE-----`
6265
)
6366

67+
func captureAgeLogs(t *testing.T) *test.Hook {
68+
t.Helper()
69+
70+
originalHooks := log.Hooks
71+
originalLevel := log.GetLevel()
72+
originalOutput := log.Out
73+
74+
log.Hooks = make(logrus.LevelHooks)
75+
hook := test.NewLocal(log)
76+
log.SetLevel(logrus.InfoLevel)
77+
log.SetOutput(io.Discard)
78+
79+
t.Cleanup(func() {
80+
log.Hooks = originalHooks
81+
log.SetLevel(originalLevel)
82+
log.SetOutput(originalOutput)
83+
})
84+
85+
return hook
86+
}
87+
6488
func TestMasterKeysFromRecipients(t *testing.T) {
6589
const otherRecipient = "age1tmaae3ld5vpevmsh5yacsauzx8jetg300mpvc4ugp5zr5l6ssq9sla97ep"
6690

@@ -179,6 +203,22 @@ func TestMasterKey_Encrypt(t *testing.T) {
179203
assert.NotEmpty(t, key.EncryptedKey)
180204
})
181205

206+
t.Run("logs recipient on success", func(t *testing.T) {
207+
key := &MasterKey{
208+
Recipient: mockRecipient,
209+
}
210+
hook := captureAgeLogs(t)
211+
212+
assert.NoError(t, key.Encrypt([]byte(mockEncryptedKeyPlain)))
213+
assert.NotEmpty(t, key.EncryptedKey)
214+
215+
entries := hook.AllEntries()
216+
if assert.Len(t, entries, 1) {
217+
assert.Equal(t, "Encryption succeeded", entries[0].Message)
218+
assert.Equal(t, mockRecipient, entries[0].Data["recipient"])
219+
}
220+
})
221+
182222
t.Run("recipient ssh", func(t *testing.T) {
183223
key := &MasterKey{
184224
Recipient: mockSshRecipient,
@@ -187,6 +227,22 @@ func TestMasterKey_Encrypt(t *testing.T) {
187227
assert.NotEmpty(t, key.EncryptedKey)
188228
})
189229

230+
t.Run("logs ssh recipient on success", func(t *testing.T) {
231+
key := &MasterKey{
232+
Recipient: mockSshRecipient,
233+
}
234+
hook := captureAgeLogs(t)
235+
236+
assert.NoError(t, key.Encrypt([]byte(mockEncryptedKeyPlain)))
237+
assert.NotEmpty(t, key.EncryptedKey)
238+
239+
entries := hook.AllEntries()
240+
if assert.Len(t, entries, 1) {
241+
assert.Equal(t, "Encryption succeeded", entries[0].Message)
242+
assert.Equal(t, mockSshRecipient, entries[0].Data["recipient"])
243+
}
244+
})
245+
190246
t.Run("parsed recipient", func(t *testing.T) {
191247
key := &MasterKey{
192248
parsedRecipient: mockParsedRecipient,
@@ -213,6 +269,24 @@ func TestMasterKey_Encrypt(t *testing.T) {
213269
assert.Empty(t, key.EncryptedKey)
214270
})
215271

272+
t.Run("logs recipient on invalid recipient failure", func(t *testing.T) {
273+
key := &MasterKey{
274+
Recipient: "invalid",
275+
}
276+
hook := captureAgeLogs(t)
277+
278+
err := key.Encrypt([]byte(mockEncryptedKeyPlain))
279+
assert.Error(t, err)
280+
assert.ErrorContains(t, err, "failed to parse input, unknown recipient type:")
281+
assert.Empty(t, key.EncryptedKey)
282+
283+
entries := hook.AllEntries()
284+
if assert.Len(t, entries, 1) {
285+
assert.Equal(t, "Encryption failed", entries[0].Message)
286+
assert.Equal(t, "invalid", entries[0].Data["recipient"])
287+
}
288+
})
289+
216290
t.Run("parsed recipient and invalid recipient", func(t *testing.T) {
217291
key := &MasterKey{
218292
Recipient: "invalid",
@@ -254,6 +328,81 @@ func TestMasterKey_Decrypt(t *testing.T) {
254328
assert.EqualValues(t, mockEncryptedKeyPlain, got)
255329
})
256330

331+
t.Run("logs recipient on success", func(t *testing.T) {
332+
key := &MasterKey{EncryptedKey: mockEncryptedKey, Recipient: mockRecipient}
333+
var ids ParsedIdentities
334+
assert.NoError(t, ids.Import(mockIdentity))
335+
ids.ApplyToMasterKey(key)
336+
hook := captureAgeLogs(t)
337+
338+
got, err := key.Decrypt()
339+
assert.NoError(t, err)
340+
assert.EqualValues(t, mockEncryptedKeyPlain, got)
341+
342+
entries := hook.AllEntries()
343+
if assert.Len(t, entries, 1) {
344+
assert.Equal(t, "Decryption succeeded", entries[0].Message)
345+
assert.Equal(t, mockRecipient, entries[0].Data["recipient"])
346+
}
347+
})
348+
349+
t.Run("logs ssh recipient on success", func(t *testing.T) {
350+
identity, err := parseSSHIdentityFromPrivateKeyCmdOutput([]byte(mockSshIdentity))
351+
assert.NoError(t, err)
352+
key := &MasterKey{
353+
EncryptedKey: mockEncryptedSshKey,
354+
Recipient: mockSshRecipient,
355+
parsedIdentities: ParsedIdentities{identity},
356+
}
357+
hook := captureAgeLogs(t)
358+
359+
got, err := key.Decrypt()
360+
assert.NoError(t, err)
361+
assert.EqualValues(t, mockEncryptedKeyPlain, got)
362+
363+
entries := hook.AllEntries()
364+
if assert.Len(t, entries, 1) {
365+
assert.Equal(t, "Decryption succeeded", entries[0].Message)
366+
assert.Equal(t, mockSshRecipient, entries[0].Data["recipient"])
367+
}
368+
})
369+
370+
t.Run("logs recipient on failure", func(t *testing.T) {
371+
key := &MasterKey{EncryptedKey: "invalid", Recipient: mockRecipient}
372+
var ids ParsedIdentities
373+
assert.NoError(t, ids.Import(mockIdentity))
374+
ids.ApplyToMasterKey(key)
375+
hook := captureAgeLogs(t)
376+
377+
got, err := key.Decrypt()
378+
assert.Error(t, err)
379+
assert.ErrorContains(t, err, "failed to create reader for decrypting sops data key with age")
380+
assert.Nil(t, got)
381+
382+
entries := hook.AllEntries()
383+
if assert.Len(t, entries, 1) {
384+
assert.Equal(t, "Decryption failed", entries[0].Message)
385+
assert.Equal(t, mockRecipient, entries[0].Data["recipient"])
386+
}
387+
})
388+
389+
t.Run("logs recipient on identity load failure", func(t *testing.T) {
390+
overwriteUserConfigDir(t, t.TempDir())
391+
key := &MasterKey{EncryptedKey: mockEncryptedKey, Recipient: mockRecipient}
392+
hook := captureAgeLogs(t)
393+
394+
got, err := key.Decrypt()
395+
assert.Error(t, err)
396+
assert.ErrorContains(t, err, "failed to load age identities")
397+
assert.Nil(t, got)
398+
399+
entries := hook.AllEntries()
400+
if assert.Len(t, entries, 1) {
401+
assert.Equal(t, "Decryption failed", entries[0].Message)
402+
assert.Equal(t, mockRecipient, entries[0].Data["recipient"])
403+
}
404+
})
405+
257406
t.Run("loaded identities", func(t *testing.T) {
258407
overwriteUserConfigDir(t, t.TempDir())
259408
key := &MasterKey{EncryptedKey: mockEncryptedKey}
@@ -577,9 +726,35 @@ func TestMasterKey_loadIdentities(t *testing.T) {
577726
})
578727
}
579728

729+
func clearAgeIdentityEnv(t *testing.T) {
730+
t.Helper()
731+
732+
for _, name := range []string{
733+
SopsAgeKeyEnv,
734+
SopsAgeKeyFileEnv,
735+
SopsAgeKeyCmdEnv,
736+
SopsAgeSshPrivateKeyCmdEnv,
737+
SopsAgeSshPrivateKeyFileEnv,
738+
} {
739+
name := name
740+
value, ok := os.LookupEnv(name)
741+
assert.NoError(t, os.Unsetenv(name))
742+
t.Cleanup(func() {
743+
if ok {
744+
assert.NoError(t, os.Setenv(name, value))
745+
} else {
746+
assert.NoError(t, os.Unsetenv(name))
747+
}
748+
})
749+
}
750+
}
751+
580752
// overwriteUserConfigDir sets the user config directory and the user home directory
581-
// based on the os.UserConfigDir logic.
753+
// based on the os.UserConfigDir logic. It also clears AGE identity environment
754+
// variables so tests only load identities from sources they explicitly set.
582755
func overwriteUserConfigDir(t *testing.T, path string) {
756+
clearAgeIdentityEnv(t)
757+
583758
switch runtime.GOOS {
584759
case "windows":
585760
t.Setenv("AppData", path)
@@ -607,10 +782,12 @@ func TestUserConfigDir(t *testing.T) {
607782

608783
func TestMasterKey_Identities_Passphrase(t *testing.T) {
609784
t.Run(SopsAgeKeyEnv, func(t *testing.T) {
785+
overwriteUserConfigDir(t, t.TempDir())
610786
key := &MasterKey{EncryptedKey: mockEncryptedKey}
611787
t.Setenv(SopsAgeKeyEnv, mockEncryptedIdentity)
612-
//blocks calling gpg-agent
788+
// blocks calling gpg-agent so tests use testOnlyAgePassword
613789
os.Unsetenv("XDG_RUNTIME_DIR")
790+
t.Setenv("GPG_AGENT_INFO", "")
614791
testOnlyAgePassword = mockIdentityPassphrase
615792
got, err := key.Decrypt()
616793
testOnlyAgePassword = ""
@@ -629,8 +806,9 @@ func TestMasterKey_Identities_Passphrase(t *testing.T) {
629806

630807
key := &MasterKey{EncryptedKey: mockEncryptedKey}
631808
t.Setenv(SopsAgeKeyFileEnv, keyPath)
632-
//blocks calling gpg-agent
809+
// blocks calling gpg-agent so tests use testOnlyAgePassword
633810
os.Unsetenv("XDG_RUNTIME_DIR")
811+
t.Setenv("GPG_AGENT_INFO", "")
634812
testOnlyAgePassword = mockIdentityPassphrase
635813

636814
got, err := key.Decrypt()
@@ -641,10 +819,12 @@ func TestMasterKey_Identities_Passphrase(t *testing.T) {
641819
})
642820

643821
t.Run("invalid encrypted key", func(t *testing.T) {
822+
overwriteUserConfigDir(t, t.TempDir())
644823
key := &MasterKey{EncryptedKey: "invalid"}
645824
t.Setenv(SopsAgeKeyEnv, mockEncryptedIdentity)
646-
//blocks calling gpg-agent
825+
// blocks calling gpg-agent so tests use testOnlyAgePassword
647826
os.Unsetenv("XDG_RUNTIME_DIR")
827+
t.Setenv("GPG_AGENT_INFO", "")
648828
testOnlyAgePassword = mockIdentityPassphrase
649829

650830
got, err := key.Decrypt()

0 commit comments

Comments
 (0)