diff --git a/cmd/jivetalking/debugsink.go b/cmd/jivetalking/debugsink.go new file mode 100644 index 0000000..ae940c6 --- /dev/null +++ b/cmd/jivetalking/debugsink.go @@ -0,0 +1,49 @@ +package main + +import ( + "fmt" + "os" + "path/filepath" + "sync" +) + +// debugSink is the shared, serialised writer for the debug log file. It holds +// the destination file and a mutex so concurrent writers each emit whole lines +// without interleaving. It carries no per-file prefix; per-file attribution is +// the wrapper's job (see withFilePrefix). +type debugSink struct { + mu sync.Mutex + file *os.File + disabled bool +} + +// newDebugSink builds a sink over file, which may be nil. The disabled/no-op +// case is decided once here (nil file) rather than re-checked per write under a +// race. +func newDebugSink(file *os.File) *debugSink { + return &debugSink{file: file, disabled: file == nil} +} + +// Logf formats one full line and writes it atomically against other writers. +// The signature matches BaseFilterConfig.SetLogger so the sink can back the +// shared log closure. The line format mirrors the original closure +// (fmt.Fprintf(debugLog, format+"\n", args...)) for byte-identity. +func (s *debugSink) Logf(format string, args ...any) { + if s.disabled { + return + } + s.mu.Lock() + defer s.mu.Unlock() + fmt.Fprintf(s.file, format+"\n", args...) +} + +// withFilePrefix wraps base and returns a logger that prepends a per-file +// marker (the basename of path) to the format string before delegating, so the +// args still bind to the original verbs. It owns no file and no lock; it is the +// per-worker, prefix-only seam. +func withFilePrefix(path string, base func(format string, args ...any)) func(format string, args ...any) { + marker := "[" + filepath.Base(path) + "] " + return func(format string, args ...any) { + base(marker+format, args...) + } +} diff --git a/cmd/jivetalking/debugsink_test.go b/cmd/jivetalking/debugsink_test.go new file mode 100644 index 0000000..4407d36 --- /dev/null +++ b/cmd/jivetalking/debugsink_test.go @@ -0,0 +1,170 @@ +package main + +import ( + "bufio" + "fmt" + "os" + "path/filepath" + "regexp" + "strings" + "sync" + "testing" +) + +// TestDebugSinkConcurrentWritesRace fans many goroutines through one shared +// sink. Run under `CGO_ENABLED=1 go test -race` to detect data races on the +// shared file and mutex. +func TestDebugSinkConcurrentWritesRace(t *testing.T) { + path := filepath.Join(t.TempDir(), "race.log") + file, err := os.Create(path) + if err != nil { + t.Fatalf("create temp file: %v", err) + } + defer file.Close() + + sink := newDebugSink(file) + + const ( + workers = 16 + linesPerWorker = 500 + ) + + var wg sync.WaitGroup + wg.Add(workers) + for w := range workers { + go func(id int) { + defer wg.Done() + for i := range linesPerWorker { + sink.Logf("worker %d line %d", id, i) + } + }(w) + } + wg.Wait() + + if err := file.Close(); err != nil { + t.Fatalf("close temp file: %v", err) + } + + lines := readLines(t, path) + if got, want := len(lines), workers*linesPerWorker; got != want { + t.Fatalf("line count = %d, want %d", got, want) + } +} + +// TestDebugSinkPrefixAttribution drives MANY per-file withFilePrefix wrappers +// over ONE shared sink with concurrent writes, then asserts every output line +// is whole (no mid-line interleaving) and carries exactly one file marker that +// matches the wrapper that produced it. +func TestDebugSinkPrefixAttribution(t *testing.T) { + path := filepath.Join(t.TempDir(), "attrib.log") + file, err := os.Create(path) + if err != nil { + t.Fatalf("create temp file: %v", err) + } + defer file.Close() + + sink := newDebugSink(file) + + const ( + wrappers = 12 + linesPerWriter = 400 + ) + + // One distinct marker per wrapper; basename drives the marker text. + names := make([]string, wrappers) + markers := make([]string, wrappers) + for w := range wrappers { + names[w] = fmt.Sprintf("episode-%02d.wav", w) + markers[w] = "[" + names[w] + "] " + } + + var wg sync.WaitGroup + wg.Add(wrappers) + for w := range wrappers { + go func(id int) { + defer wg.Done() + logf := withFilePrefix(names[id], sink.Logf) + for i := range linesPerWriter { + logf("payload writer %d seq %d", id, i) + } + }(w) + } + wg.Wait() + + if err := file.Close(); err != nil { + t.Fatalf("close temp file: %v", err) + } + + lines := readLines(t, path) + if got, want := len(lines), wrappers*linesPerWriter; got != want { + t.Fatalf("line count = %d, want %d", got, want) + } + + // A whole, well-formed line is exactly one marker followed by a payload + // naming the same writer id as the marker. Any interleaving breaks this. + markerRe := regexp.MustCompile(`\[episode-\d{2}\.wav\] `) + lineRe := regexp.MustCompile(`^\[episode-(\d{2})\.wav\] payload writer (\d+) seq \d+$`) + + seen := make([]int, wrappers) + for n, line := range lines { + // Exactly one marker per line (no mid-line interleaving). + if count := len(markerRe.FindAllString(line, -1)); count != 1 { + t.Fatalf("line %d has %d markers, want 1: %q", n, count, line) + } + m := lineRe.FindStringSubmatch(line) + if m == nil { + t.Fatalf("line %d malformed: %q", n, line) + } + // The marker's writer id must match the payload's writer id. + if m[1] != fmt.Sprintf("%02d", mustAtoi(t, m[2])) { + t.Fatalf("line %d marker/payload writer mismatch: %q", n, line) + } + id := mustAtoi(t, m[2]) + if id < 0 || id >= wrappers { + t.Fatalf("line %d writer id %d out of range", n, id) + } + // The line carries the exact marker string for that writer. + if !strings.HasPrefix(line, markers[id]) { + t.Fatalf("line %d prefix %q, want marker %q", n, line, markers[id]) + } + seen[id]++ + } + + for id, count := range seen { + if count != linesPerWriter { + t.Fatalf("writer %d produced %d lines, want %d", id, count, linesPerWriter) + } + } +} + +func readLines(t *testing.T, path string) []string { + t.Helper() + f, err := os.Open(path) + if err != nil { + t.Fatalf("open %s: %v", path, err) + } + defer f.Close() + + var lines []string + sc := bufio.NewScanner(f) + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for sc.Scan() { + lines = append(lines, sc.Text()) + } + if err := sc.Err(); err != nil { + t.Fatalf("scan %s: %v", path, err) + } + return lines +} + +func mustAtoi(t *testing.T, s string) int { + t.Helper() + n := 0 + for _, r := range s { + if r < '0' || r > '9' { + t.Fatalf("non-numeric value %q", s) + } + n = n*10 + int(r-'0') + } + return n +} diff --git a/cmd/jivetalking/main.go b/cmd/jivetalking/main.go index bfdb303..6319262 100644 --- a/cmd/jivetalking/main.go +++ b/cmd/jivetalking/main.go @@ -112,10 +112,9 @@ func main() { if debugLog != nil { defer debugLog.Close() } + sink := newDebugSink(debugLog) log := func(format string, args ...any) { - if debugLog != nil { - fmt.Fprintf(debugLog, format+"\n", args...) - } + sink.Logf(format, args...) } // Set the config's debug log function to use the same log @@ -148,8 +147,9 @@ func main() { // Create progress handler ph := &progressHandler{ - p: p, - log: log, + p: p, + log: log, + fileIndex: i, } // Process the audio file @@ -277,6 +277,7 @@ func (ph *progressHandler) timings(pass2Time time.Duration) logging.ProcessingTi type progressHandler struct { p *tea.Program log func(string, ...any) + fileIndex int pass1Start time.Time pass1Time time.Duration pass3Start time.Time @@ -305,6 +306,7 @@ func (ph *progressHandler) callback(update processor.ProgressUpdate) { } ph.p.Send(ui.ProgressMsg{ + FileIndex: ph.fileIndex, Pass: update.Pass, PassName: update.PassName, Progress: update.Progress, diff --git a/internal/ui/messages.go b/internal/ui/messages.go index 3b1ec3f..feff658 100644 --- a/internal/ui/messages.go +++ b/internal/ui/messages.go @@ -6,6 +6,7 @@ import ( // ProgressMsg represents a progress update from the processor type ProgressMsg struct { + FileIndex int Pass processor.PassNumber PassName string Progress float64 diff --git a/internal/ui/model.go b/internal/ui/model.go index 62a4b74..ff87efa 100644 --- a/internal/ui/model.go +++ b/internal/ui/model.go @@ -56,7 +56,6 @@ type FileProgress struct { type Model struct { // File queue Files []FileProgress - CurrentIndex int TotalFiles int CompletedFiles int FailedFiles int @@ -82,10 +81,9 @@ func NewModel(inputFiles []string) Model { } return Model{ - Files: files, - CurrentIndex: -1, // No file processing yet - TotalFiles: len(inputFiles), - StartTime: time.Now(), + Files: files, + TotalFiles: len(inputFiles), + StartTime: time.Now(), } } @@ -109,30 +107,31 @@ func (m Model) Update(msg tea.Msg) (tea.Model, tea.Cmd) { case ProgressMsg: // Update the current file's progress - if m.CurrentIndex >= 0 && m.CurrentIndex < len(m.Files) { - m.Files[m.CurrentIndex] = updateFileProgress(m.Files[m.CurrentIndex], msg) + if msg.FileIndex >= 0 && msg.FileIndex < len(m.Files) { + m.Files[msg.FileIndex] = updateFileProgress(m.Files[msg.FileIndex], msg) } return m, nil case FileStartMsg: // Start processing next file - m.CurrentIndex = msg.FileIndex - m.Files[m.CurrentIndex].Status = StatusAnalyzing - m.Files[m.CurrentIndex].StartTime = time.Now() + if msg.FileIndex >= 0 && msg.FileIndex < len(m.Files) { + m.Files[msg.FileIndex].Status = StatusAnalyzing + m.Files[msg.FileIndex].StartTime = time.Now() + } return m, nil case FileCompleteMsg: // Mark file as complete - if m.CurrentIndex >= 0 && m.CurrentIndex < len(m.Files) { - m.Files[m.CurrentIndex].Status = StatusComplete - m.Files[m.CurrentIndex].InputLUFS = msg.InputLUFS - m.Files[m.CurrentIndex].OutputLUFS = msg.OutputLUFS - m.Files[m.CurrentIndex].NoiseFloor = msg.NoiseFloor - m.Files[m.CurrentIndex].OutputPath = msg.OutputPath - m.Files[m.CurrentIndex].Error = msg.Error + if msg.FileIndex >= 0 && msg.FileIndex < len(m.Files) { + m.Files[msg.FileIndex].Status = StatusComplete + m.Files[msg.FileIndex].InputLUFS = msg.InputLUFS + m.Files[msg.FileIndex].OutputLUFS = msg.OutputLUFS + m.Files[msg.FileIndex].NoiseFloor = msg.NoiseFloor + m.Files[msg.FileIndex].OutputPath = msg.OutputPath + m.Files[msg.FileIndex].Error = msg.Error if msg.Error != nil { - m.Files[m.CurrentIndex].Status = StatusError + m.Files[msg.FileIndex].Status = StatusError m.FailedFiles++ } else { m.CompletedFiles++ @@ -153,7 +152,7 @@ func (m Model) Update(msg tea.Msg) (tea.Model, tea.Cmd) { func (m Model) View() string { // Debug: Show basic info even before window size is set if m.Width == 0 { - return fmt.Sprintf("Initializing...\nFiles: %d\nCurrent: %d\n", len(m.Files), m.CurrentIndex) + return fmt.Sprintf("Initializing...\nFiles: %d\n", len(m.Files)) } // Build the view based on current state diff --git a/internal/ui/model_routing_test.go b/internal/ui/model_routing_test.go new file mode 100644 index 0000000..50ca56e --- /dev/null +++ b/internal/ui/model_routing_test.go @@ -0,0 +1,109 @@ +package ui + +import ( + "errors" + "strings" + "testing" + + "github.com/linuxmatters/jivetalking/internal/processor" +) + +func TestProgressMsgIndexRouting(t *testing.T) { + m := NewModel([]string{"a.wav", "b.wav"}) + + updated, _ := m.Update(ProgressMsg{FileIndex: 0, Pass: processor.PassAnalysis, Progress: 0.25}) + m = updated.(Model) + updated, _ = m.Update(ProgressMsg{FileIndex: 1, Pass: processor.PassProcessing, Progress: 0.75}) + m = updated.(Model) + + if m.Files[0].Progress != 0.25 { + t.Errorf("Files[0].Progress = %v, want 0.25", m.Files[0].Progress) + } + if m.Files[0].CurrentPass != processor.PassAnalysis { + t.Errorf("Files[0].CurrentPass = %v, want PassAnalysis", m.Files[0].CurrentPass) + } + if m.Files[0].Status != StatusAnalyzing { + t.Errorf("Files[0].Status = %v, want StatusAnalyzing", m.Files[0].Status) + } + + if m.Files[1].Progress != 0.75 { + t.Errorf("Files[1].Progress = %v, want 0.75", m.Files[1].Progress) + } + if m.Files[1].CurrentPass != processor.PassProcessing { + t.Errorf("Files[1].CurrentPass = %v, want PassProcessing", m.Files[1].CurrentPass) + } + if m.Files[1].Status != StatusProcessing { + t.Errorf("Files[1].Status = %v, want StatusProcessing", m.Files[1].Status) + } +} + +func TestFileCompleteMsgIndexRouting(t *testing.T) { + m := NewModel([]string{"a.wav", "b.wav"}) + + // Put index 0 mid-process. + updated, _ := m.Update(ProgressMsg{FileIndex: 0, Pass: processor.PassProcessing, Progress: 0.5}) + m = updated.(Model) + before := m.Files[0] + + updated, _ = m.Update(FileCompleteMsg{FileIndex: 1, InputLUFS: -23, OutputLUFS: -16, OutputPath: "b-out.wav"}) + m = updated.(Model) + + if m.Files[1].Status != StatusComplete { + t.Errorf("Files[1].Status = %v, want StatusComplete", m.Files[1].Status) + } + if m.Files[1].OutputPath != "b-out.wav" { + t.Errorf("Files[1].OutputPath = %q, want b-out.wav", m.Files[1].OutputPath) + } + if m.Files[0] != before { + t.Errorf("Files[0] changed: got %+v, want %+v", m.Files[0], before) + } +} + +func TestUpdateOutOfRangeSafety(t *testing.T) { + m := NewModel([]string{"a.wav", "b.wav"}) + want := append([]FileProgress(nil), m.Files...) + + indices := []int{-1, len(m.Files)} + for _, idx := range indices { + updated, _ := m.Update(ProgressMsg{FileIndex: idx, Pass: processor.PassProcessing, Progress: 0.9}) + m = updated.(Model) + updated, _ = m.Update(FileCompleteMsg{FileIndex: idx, OutputPath: "x"}) + m = updated.(Model) + } + + for i := range want { + if m.Files[i] != want[i] { + t.Errorf("Files[%d] changed after out-of-range messages: got %+v, want %+v", i, m.Files[i], want[i]) + } + } + if m.CompletedFiles != 0 || m.FailedFiles != 0 { + t.Errorf("counts changed: completed=%d failed=%d, want 0/0", m.CompletedFiles, m.FailedFiles) + } +} + +func TestRenderOverallProgressFooter(t *testing.T) { + m := NewModel([]string{"a.wav", "b.wav", "c.wav"}) + + // One complete, one failed, one in progress. + updated, _ := m.Update(FileCompleteMsg{FileIndex: 0, OutputPath: "a-out.wav"}) + m = updated.(Model) + updated, _ = m.Update(FileCompleteMsg{FileIndex: 1, Error: errors.New("boom")}) + m = updated.(Model) + updated, _ = m.Update(ProgressMsg{FileIndex: 2, Pass: processor.PassProcessing, Progress: 0.4}) + m = updated.(Model) + + footer := renderOverallProgress(m) + + if !strings.Contains(footer, "3") { + t.Errorf("footer missing total count 3: %q", footer) + } + if !strings.Contains(footer, "1 complete") { + t.Errorf("footer missing complete count: %q", footer) + } + if !strings.Contains(footer, "1 failed") { + t.Errorf("footer missing failed count: %q", footer) + } + if strings.Contains(strings.ToLower(footer), "file 3 of") || strings.Contains(strings.ToLower(footer), "of 3") { + t.Errorf("footer must not contain a 'file N of M' cursor: %q", footer) + } +} diff --git a/internal/ui/views.go b/internal/ui/views.go index 10392a3..9403b14 100644 --- a/internal/ui/views.go +++ b/internal/ui/views.go @@ -219,15 +219,8 @@ func renderOverallProgress(m Model) string { BorderForeground(lipgloss.Color("#888888")). Padding(0, 1) - // Show current file being processed - var content string - if m.CurrentIndex >= 0 && m.CurrentIndex < len(m.Files) { - currentFile := m.CurrentIndex + 1 // 1-indexed for display - content = fmt.Sprintf("Processing file %d of %d (%d complete)", - currentFile, m.TotalFiles, m.CompletedFiles) - } else { - content = fmt.Sprintf("Overall Progress: %d/%d complete", m.CompletedFiles, m.TotalFiles) - } + content := fmt.Sprintf("Processing %d files, %d complete, %d failed", + m.TotalFiles, m.CompletedFiles, m.FailedFiles) return box.Render(content) }