spindle/models: hold back a trailing window so secrets split across log writes stay masked #9

+41 -8

spindle/models/logger.go

Reviewed

··· 24 24 } 25 25 26 26 type FileWorkflowLogger struct { 27 27 - file *os.File 28 28 - encoder *json.Encoder 29 29 - mask *SecretMask 27 27 + file *os.File 28 28 + encoder *json.Encoder 29 29 + mask *SecretMask 30 30 + dataWriters []*dataWriter 30 31 } 31 32 32 33 func NewFileWorkflowLogger(baseDir string, wid WorkflowId, secretValues []string) (WorkflowLogger, error) { ··· 48 49 } 49 50 50 51 func (l *FileWorkflowLogger) Close() error { 52 52 + for _, w := range l.dataWriters { 53 53 + if err := w.flush(); err != nil { 54 54 + return err 55 55 + } 56 56 + } 51 57 return l.file.Close() 52 58 } 53 59 54 60 func (l *FileWorkflowLogger) DataWriter(idx int, stream string) io.Writer { 55 55 - return &dataWriter{ 61 61 + w := &dataWriter{ 56 62 logger: l, 57 63 idx: idx, 58 64 stream: stream, 59 65 } 66 66 + l.dataWriters = append(l.dataWriters, w) 67 67 + return w 60 68 } 61 69 62 70 func (l *FileWorkflowLogger) ControlWriter(idx int, step Step, stepStatus StepStatus) io.Writer { ··· 72 80 logger *FileWorkflowLogger 73 81 idx int 74 82 stream string 83 83 + // trailing bytes held back so a secret split across writes still 84 84 + // matches, flushed on Close or once enough data arrives 85 85 + pending []byte 75 86 } 76 87 77 88 func (w *dataWriter) Write(p []byte) (int, error) { 89 89 + w.pending = append(w.pending, p...) 90 90 + window := w.logger.mask.Window() 91 91 + // anything within window of the tail might be half a secret, keep 92 92 + // it buffered 93 93 + if len(w.pending) <= window { 94 94 + return len(p), nil 95 95 + } 96 96 + emit := w.pending[:len(w.pending)-window] 97 97 + // copy the tail out, emit still aliases the same backing array 98 98 + w.pending = append([]byte(nil), w.pending[len(w.pending)-window:]...) 99 99 + return len(p), w.emit(emit) 100 100 + } 101 101 + 102 102 + // the writer is done, so a buffered tail can no longer grow into a 103 103 + // full secret and goes out as-is 104 104 + func (w *dataWriter) flush() error { 105 105 + if len(w.pending) == 0 { 106 106 + return nil 107 107 + } 108 108 + pending := w.pending 109 109 + w.pending = nil 110 110 + return w.emit(pending) 111 111 + } 112 112 + 113 113 + func (w *dataWriter) emit(p []byte) error { 78 114 line := strings.TrimRight(string(p), "\r\n") 79 115 if w.logger.mask != nil { 80 116 line = w.logger.mask.Mask(line) 81 117 } 82 118 entry := NewDataLogLine(w.idx, line, w.stream) 83 83 - if err := w.logger.encoder.Encode(entry); err != nil { 84 84 - return 0, err 85 85 - } 86 86 - return len(p), nil 119 119 + return w.logger.encoder.Encode(entry) 87 120 } 88 121 89 122 type controlWriter struct {

+102

spindle/models/logger_test.go

Reviewed

··· 1 1 + package models 2 2 + 3 3 + import ( 4 4 + "os" 5 5 + "path/filepath" 6 6 + "strings" 7 7 + "testing" 8 8 + ) 9 9 + 10 10 + func testWorkflowId(name string) WorkflowId { 11 11 + return WorkflowId{PipelineId: PipelineId{Knot: "knot1", Rkey: "rkey1"}, Name: name} 12 12 + } 13 13 + 14 14 + func TestDataWriterMasksSecretSplitAcrossWrites(t *testing.T) { 15 15 + dir := t.TempDir() 16 16 + secret := "hunter2-super-secret-token" 17 17 + wid := testWorkflowId("mask") 18 18 + logger, err := NewFileWorkflowLogger(dir, wid, []string{secret}) 19 19 + if err != nil { 20 20 + t.Fatal(err) 21 21 + } 22 22 + w := logger.DataWriter(0, "stdout") 23 23 + 24 24 + for _, ch := range strings.Split("prefix "+secret+" suffix", "") { 25 25 + if _, err := w.Write([]byte(ch)); err != nil { 26 26 + t.Fatal(err) 27 27 + } 28 28 + } 29 29 + if err := logger.Close(); err != nil { 30 30 + t.Fatal(err) 31 31 + } 32 32 + 33 33 + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) 34 34 + if err != nil { 35 35 + t.Fatal(err) 36 36 + } 37 37 + if strings.Contains(string(raw), secret) { 38 38 + t.Errorf("log contains raw secret: %s", raw) 39 39 + } 40 40 + if !strings.Contains(string(raw), "***") { 41 41 + t.Errorf("log does not contain masked marker: %s", raw) 42 42 + } 43 43 + // trailing bytes land in the final flush entry contiguously 44 44 + if !strings.Contains(string(raw), "suffix") { 45 45 + t.Errorf("log lost trailing output: %s", raw) 46 46 + } 47 47 + } 48 48 + 49 49 + func TestDataWriterMasksSingleFrame(t *testing.T) { 50 50 + dir := t.TempDir() 51 51 + secret := "hunter2-super-secret-token" 52 52 + wid := testWorkflowId("frame") 53 53 + logger, err := NewFileWorkflowLogger(dir, wid, []string{secret}) 54 54 + if err != nil { 55 55 + t.Fatal(err) 56 56 + } 57 57 + w := logger.DataWriter(0, "stdout") 58 58 + if _, err := w.Write([]byte("token is " + secret + " ok")); err != nil { 59 59 + t.Fatal(err) 60 60 + } 61 61 + if err := logger.Close(); err != nil { 62 62 + t.Fatal(err) 63 63 + } 64 64 + 65 65 + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) 66 66 + if err != nil { 67 67 + t.Fatal(err) 68 68 + } 69 69 + if strings.Contains(string(raw), secret) { 70 70 + t.Errorf("log contains raw secret: %s", raw) 71 71 + } 72 72 + if !strings.Contains(string(raw), "en is *** ok") { 73 73 + t.Errorf("masked entry mangled: %s", raw) 74 74 + } 75 75 + } 76 76 + 77 77 + func TestDataWriterNoMaskPassthrough(t *testing.T) { 78 78 + dir := t.TempDir() 79 79 + wid := testWorkflowId("plain") 80 80 + logger, err := NewFileWorkflowLogger(dir, wid, nil) 81 81 + if err != nil { 82 82 + t.Fatal(err) 83 83 + } 84 84 + w := logger.DataWriter(0, "stdout") 85 85 + if _, err := w.Write([]byte("hello")); err != nil { 86 86 + t.Fatal(err) 87 87 + } 88 88 + if _, err := w.Write([]byte(" world")); err != nil { 89 89 + t.Fatal(err) 90 90 + } 91 91 + if err := logger.Close(); err != nil { 92 92 + t.Fatal(err) 93 93 + } 94 94 + 95 95 + raw, err := os.ReadFile(filepath.Join(dir, wid.String()+".log")) 96 96 + if err != nil { 97 97 + t.Fatal(err) 98 98 + } 99 99 + if !strings.Contains(string(raw), "hello") || !strings.Contains(string(raw), " world") { 100 100 + t.Errorf("log missing output: %s", raw) 101 101 + } 102 102 + }

+22

spindle/models/secret_mask.go

Reviewed

··· 8 8 // SecretMask replaces secret values in strings with "***". 9 9 type SecretMask struct { 10 10 replacer *strings.Replacer 11 11 + // length of the longest secret. writers keep the last window-1 12 12 + // bytes unflushed so a secret split across writes can still match 13 13 + // whole 14 14 + window int 11 15 } 12 16 13 17 // NewSecretMask creates a mask for the given secret values. ··· 37 41 return nil 38 42 } 39 43 44 44 + window := 0 45 45 + for i := 0; i < len(pairs); i += 2 { 46 46 + window = max(window, len(pairs[i])) 47 47 + } 48 48 + 40 49 return &SecretMask{ 41 50 replacer: strings.NewReplacer(pairs...), 51 51 + window: window, 52 52 + } 53 53 + } 54 54 + 55 55 + // trailing bytes a streaming caller must keep unflushed so a secret 56 56 + // spanning a write boundary still matches 57 57 + func (m *SecretMask) Window() int { 58 58 + if m == nil { 59 59 + return 0 60 60 + } 61 61 + if m.window <= 1 { 62 62 + return 0 42 63 } 64 64 + return m.window - 1 43 65 } 44 66 45 67 // Mask replaces all registered secret values with "***".