diff --git a/spindle/models/logger.go b/spindle/models/logger.go index abc7f1be..6acd3ac8 100644 --- a/spindle/models/logger.go +++ b/spindle/models/logger.go @@ -24,9 +24,10 @@ func (l NullLogger) ControlWriter(idx int, step Step, stepStatus StepStatus) io. } type FileWorkflowLogger struct { - file *os.File - encoder *json.Encoder - mask *SecretMask + file *os.File + encoder *json.Encoder + mask *SecretMask + dataWriters []*dataWriter } func NewFileWorkflowLogger(baseDir string, wid WorkflowId, secretValues []string) (WorkflowLogger, error) { @@ -48,15 +49,22 @@ func LogFilePath(baseDir string, workflowID WorkflowId) string { } func (l *FileWorkflowLogger) Close() error { + for _, w := range l.dataWriters { + if err := w.flush(); err != nil { + return err + } + } return l.file.Close() } func (l *FileWorkflowLogger) DataWriter(idx int, stream string) io.Writer { - return &dataWriter{ + w := &dataWriter{ logger: l, idx: idx, stream: stream, } + l.dataWriters = append(l.dataWriters, w) + return w } func (l *FileWorkflowLogger) ControlWriter(idx int, step Step, stepStatus StepStatus) io.Writer { @@ -72,18 +80,43 @@ type dataWriter struct { logger *FileWorkflowLogger idx int stream string + // trailing bytes held back so a secret split across writes still + // matches, flushed on Close or once enough data arrives + pending []byte } 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 + } + 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) +} + +// 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 + } + pending := w.pending + w.pending = nil + return w.emit(pending) +} + +func (w *dataWriter) emit(p []byte) error { line := strings.TrimRight(string(p), "\r\n") if w.logger.mask != nil { line = w.logger.mask.Mask(line) } entry := NewDataLogLine(w.idx, line, w.stream) - if err := w.logger.encoder.Encode(entry); err != nil { - return 0, err - } - return len(p), nil + return w.logger.encoder.Encode(entry) } type controlWriter struct { diff --git a/spindle/models/logger_test.go b/spindle/models/logger_test.go new file mode 100644 index 00000000..686583e4 --- /dev/null +++ b/spindle/models/logger_test.go @@ -0,0 +1,102 @@ +package models + +import ( + "os" + "path/filepath" + "strings" + "testing" +) + +func testWorkflowId(name string) WorkflowId { + return WorkflowId{PipelineId: PipelineId{Knot: "knot1", Rkey: "rkey1"}, Name: name} +} + +func TestDataWriterMasksSecretSplitAcrossWrites(t *testing.T) { + dir := t.TempDir() + secret := "hunter2-super-secret-token" + wid := testWorkflowId("mask") + logger, err := NewFileWorkflowLogger(dir, wid, []string{secret}) + if err != nil { + t.Fatal(err) + } + w := logger.DataWriter(0, "stdout") + + for _, ch := range strings.Split("prefix "+secret+" suffix", "") { + if _, err := w.Write([]byte(ch)); err != nil { + t.Fatal(err) + } + } + if err := logger.Close(); err != nil { + t.Fatal(err) + } + + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(raw), secret) { + t.Errorf("log contains raw secret: %s", raw) + } + if !strings.Contains(string(raw), "***") { + t.Errorf("log does not contain masked marker: %s", raw) + } + // trailing bytes land in the final flush entry contiguously + if !strings.Contains(string(raw), "suffix") { + t.Errorf("log lost trailing output: %s", raw) + } +} + +func TestDataWriterMasksSingleFrame(t *testing.T) { + dir := t.TempDir() + secret := "hunter2-super-secret-token" + wid := testWorkflowId("frame") + logger, err := NewFileWorkflowLogger(dir, wid, []string{secret}) + if err != nil { + t.Fatal(err) + } + w := logger.DataWriter(0, "stdout") + if _, err := w.Write([]byte("token is " + secret + " ok")); err != nil { + t.Fatal(err) + } + if err := logger.Close(); err != nil { + t.Fatal(err) + } + + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(raw), secret) { + t.Errorf("log contains raw secret: %s", raw) + } + if !strings.Contains(string(raw), "en is *** ok") { + t.Errorf("masked entry mangled: %s", raw) + } +} + +func TestDataWriterNoMaskPassthrough(t *testing.T) { + dir := t.TempDir() + wid := testWorkflowId("plain") + logger, err := NewFileWorkflowLogger(dir, wid, nil) + if err != nil { + t.Fatal(err) + } + w := logger.DataWriter(0, "stdout") + if _, err := w.Write([]byte("hello")); err != nil { + t.Fatal(err) + } + if _, err := w.Write([]byte(" world")); err != nil { + t.Fatal(err) + } + if err := logger.Close(); err != nil { + t.Fatal(err) + } + + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) + if err != nil { + t.Fatal(err) + } + if !strings.Contains(string(raw), "hello") || !strings.Contains(string(raw), " world") { + t.Errorf("log missing output: %s", raw) + } +} diff --git a/spindle/models/secret_mask.go b/spindle/models/secret_mask.go index 29b01d2d..840aa5f7 100644 --- a/spindle/models/secret_mask.go +++ b/spindle/models/secret_mask.go @@ -8,6 +8,10 @@ import ( // SecretMask replaces secret values in strings with "***". type SecretMask struct { replacer *strings.Replacer + // length of the longest secret. writers keep the last window-1 + // bytes unflushed so a secret split across writes can still match + // whole + window int } // NewSecretMask creates a mask for the given secret values. @@ -37,9 +41,27 @@ func NewSecretMask(values []string) *SecretMask { return nil } + window := 0 + for i := 0; i < len(pairs); i += 2 { + window = max(window, len(pairs[i])) + } + return &SecretMask{ replacer: strings.NewReplacer(pairs...), + window: window, + } +} + +// trailing bytes a streaming caller must keep unflushed so a secret +// spanning a write boundary still matches +func (m *SecretMask) Window() int { + if m == nil { + return 0 + } + if m.window <= 1 { + return 0 } + return m.window - 1 } // Mask replaces all registered secret values with "***".