diff --git a/spindle/models/logger.go b/spindle/models/logger.go --- a/spindle/models/logger.go +++ b/spindle/models/logger.go @@ -1,6 +1,7 @@ package models import ( + "bytes" "encoding/json" "fmt" "io" @@ -87,20 +88,35 @@ func (w *dataWriter) Write(p []byte) (int, error) { w.pending = append(w.pending, p...) - window := w.logger.mask.Window() - // anything within window of the tail might be half a secret, keep - // it buffered - if len(w.pending) <= window { - return len(p), nil + if err := w.flushCompleteLines(); err != nil { + return 0, err } - emit := w.pending[:len(w.pending)-window] - // copy the tail out, emit still aliases the same backing array - w.pending = append([]byte(nil), w.pending[len(w.pending)-window:]...) - return len(p), w.emit(emit) + return len(p), nil } -// the writer is done, so a buffered tail can no longer grow into a -// full secret and goes out as-is +func (w *dataWriter) flushCompleteLines() error { + limit := len(w.pending) - w.logger.mask.Window() + if limit <= 0 { + return nil + } + + for { + lineEnd := bytes.IndexByte(w.pending[:limit], '\n') + if lineEnd < 0 { + return nil + } + lineEnd++ + line := append([]byte(nil), w.pending[:lineEnd]...) + w.pending = w.pending[lineEnd:] + limit -= lineEnd + if err := w.emit(line); err != nil { + return err + } + } +} + +// the writer is done, so a buffered tail can no longer grow into a full +// secret and goes out as-is func (w *dataWriter) flush() error { if len(w.pending) == 0 { return nil diff --git a/spindle/models/logger_test.go b/spindle/models/logger_test.go --- a/spindle/models/logger_test.go +++ b/spindle/models/logger_test.go @@ -1,6 +1,7 @@ package models import ( + "encoding/json" "os" "path/filepath" "strings" @@ -9,6 +10,24 @@ func testWorkflowId(name string) WorkflowId { return WorkflowId{PipelineId: PipelineId{Knot: "knot1", Rkey: "rkey1"}, Name: name} +} + +func readDataContents(t *testing.T, path string) []string { + t.Helper() + raw, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + + var got []string + for _, encoded := range strings.Split(strings.TrimSpace(string(raw)), "\n") { + var line LogLine + if err := json.Unmarshal([]byte(encoded), &line); err != nil { + t.Fatalf("decode log line %q: %v", encoded, err) + } + got = append(got, line.Content) + } + return got } func TestDataWriterMasksSecretSplitAcrossWrites(t *testing.T) { @@ -43,6 +62,9 @@ // trailing bytes land in the final flush entry contiguously if !strings.Contains(string(raw), "suffix") { t.Errorf("log lost trailing output: %s", raw) + } + if got := strings.Join(readDataContents(t, filepath.Join(dir, wid.String()+".log")), "\n"); got != "prefix *** suffix" { + t.Errorf("masked output changed: %q", got) } } @@ -98,5 +120,63 @@ } if !strings.Contains(string(raw), "hello") || !strings.Contains(string(raw), " world") { t.Errorf("log missing output: %s", raw) + } +} + +func TestDataWriterDoesNotSplitSafeFragmentsIntoLogLines(t *testing.T) { + dir := t.TempDir() + wid := testWorkflowId("line-boundaries") + logger, err := NewFileWorkflowLogger(dir, wid, []string{"a-secret-with-a-long-window"}) + if err != nil { + t.Fatal(err) + } + w := logger.DataWriter(0, "stdout") + want := []string{ + "first line", + "second line", + "third line", + "fourth line", + "fifth line", + "sixth line", + "seventh line", + "eighth line", + } + for _, line := range want { + if _, err := w.Write([]byte(line + "\n")); err != nil { + t.Fatal(err) + } + } + if err := logger.Close(); err != nil { + t.Fatal(err) + } + + got := readDataContents(t, filepath.Join(dir, wid.String()+".log")) + + if joined := strings.Join(got, "\n"); joined != strings.Join(want, "\n") { + t.Fatalf("log content was split at masking window:\n got: %q\nwant: %q", joined, strings.Join(want, "\n")) + } +} + +func TestDataWriterMasksMultilineSecret(t *testing.T) { + dir := t.TempDir() + secret := "line-one\nline-two" + wid := testWorkflowId("multiline-mask") + logger, err := NewFileWorkflowLogger(dir, wid, []string{secret}) + if err != nil { + t.Fatal(err) + } + w := logger.DataWriter(0, "stdout") + chunk := strings.Repeat("p", 40) + "\nline-one\nline-two\n" + strings.Repeat("t", 30) + "\nsuffix\n" + if _, err := w.Write([]byte(chunk)); err != nil { + t.Fatal(err) + } + if err := logger.Close(); err != nil { + t.Fatal(err) + } + + got := strings.Join(readDataContents(t, filepath.Join(dir, wid.String()+".log")), "\n") + want := strings.Repeat("p", 40) + "\n***\n***\n" + strings.Repeat("t", 30) + "\nsuffix" + if got != want { + t.Fatalf("multiline secret was not masked: %q", got) } } diff --git a/spindle/models/secret_mask.go b/spindle/models/secret_mask.go --- a/spindle/models/secret_mask.go +++ b/spindle/models/secret_mask.go @@ -18,22 +18,34 @@ // Also registers base64-encoded variants of each secret. func NewSecretMask(values []string) *SecretMask { var pairs []string + add := func(value string) { + if value != "" { + pairs = append(pairs, value, "***") + } + } for _, value := range values { if value == "" { continue } - pairs = append(pairs, value, "***") + add(value) + // mask each non-empty line of a multiline secret + // output may split a secret over multiple log lines... + for _, line := range strings.FieldsFunc(value, func(r rune) bool { + return r == '\r' || r == '\n' + }) { + add(line) + } b64 := base64.StdEncoding.EncodeToString([]byte(value)) if b64 != value { - pairs = append(pairs, b64, "***") + add(b64) } b64NoPad := strings.TrimRight(b64, "=") if b64NoPad != b64 && b64NoPad != value { - pairs = append(pairs, b64NoPad, "***") + add(b64NoPad) } } diff --git a/spindle/models/secret_mask_test.go b/spindle/models/secret_mask_test.go --- a/spindle/models/secret_mask_test.go +++ b/spindle/models/secret_mask_test.go @@ -133,3 +133,16 @@ t.Errorf("expected %q, got %q", expected, result) } } + +func TestSecretMask_MultilineSecretLines(t *testing.T) { + mask := NewSecretMask([]string{"line-one\nline-two"}) + + if result := mask.Mask("line-one\nline-two"); result != "***" { + t.Errorf("full multiline secret: expected %q, got %q", "***", result) + } + for _, line := range []string{"line-one", "line-two"} { + if result := mask.Mask(line); result != "***" { + t.Errorf("secret line %q: expected %q, got %q", line, "***", result) + } + } +}