v0.35.0 tui fixes

internal/source/file/file.go

@@ -44,6 +44,7 @@ type FileSource struct {
 	// already reported, touched only by monitorLoop.
 	own        []os.FileInfo
 	ownSkipped map[string]bool
+	scanErr    string // the last scan's error, "" once it read; monitorLoop's
 
 	// Application
 	subscribers []chan core.LogEntry
@@ -138,7 +139,7 @@ func (fs *FileSource) Start() error {
 	go fs.monitorLoop()
 
 	fs.logger.Info("msg", "File source started",
-		"component", "File_source",
+		"component", "file_source",
 		"path", fs.config.Directory,
 		"pattern", fs.config.Pattern,
 		"check_interval_ms", fs.config.CheckIntervalMS)
@@ -227,12 +228,8 @@ func (fs *FileSource) monitorLoop() {
 // checkTargets finds matching files and ensures watchers are running for them.
 func (fs *FileSource) checkTargets() {
 	files, err := fs.scanFile()
+	fs.noteScan(err)
 	if err != nil {
-		fs.logger.Warn("msg", "Failed to scan file",
-			"component", "file_source",
-			"path", fs.config.Directory,
-			"pattern", fs.config.Pattern,
-			"error", err)
 		return
 	}
 
@@ -243,6 +240,32 @@ func (fs *FileSource) checkTargets() {
 	fs.cleanupWatchers()
 }
 
+// noteScan logs when the directory cannot be read and when it can again, not
+// every check: a missing one at info, as it may yet be made
+func (fs *FileSource) noteScan(err error) {
+	switch {
+	case !changed(&fs.scanErr, err):
+	case err == nil:
+		fs.logger.Info("msg", "Directory readable", "component", "file_source", "instance_id", fs.id, "directory", fs.config.Directory)
+	case errors.Is(err, os.ErrNotExist):
+		fs.logger.Info("msg", "Waiting for directory", "component", "file_source", "instance_id", fs.id, "directory", fs.config.Directory)
+	default:
+		fs.logger.Warn("msg", "Cannot read directory", "component", "file_source", "instance_id", fs.id, "directory", fs.config.Directory, "error", err)
+	}
+}
+
+// changed reports whether err differs from the last check's, kept in last
+// ("" for none), so a failure is logged as it starts or changes
+func changed(last *string, err error) bool {
+	text := ""
+	if err != nil {
+		text = err.Error()
+	}
+	was := *last
+	*last = text
+	return text != was
+}
+
 // ensureWatcher creates and starts a new file watcher if one doesn't exist for the given path.
 func (fs *FileSource) ensureWatcher(path string) {
 	fs.mu.Lock()
@@ -269,16 +292,9 @@ func (fs *FileSource) ensureWatcher(path string) {
 	go func() {
 		defer fs.wg.Done()
 		if err := w.watch(fs.ctx); err != nil {
-			if errors.Is(err, context.Canceled) {
-				fs.logger.Debug("msg", "Watcher cancelled",
-					"component", "file_source",
-					"path", path)
-			} else {
-				fs.logger.Error("msg", "Watcher failed",
-					"component", "file_source",
-					"path", path,
-					"error", err)
-			}
+			fs.logger.Debug("msg", "Watcher cancelled",
+				"component", "file_source",
+				"path", path)
 		}
 
 		fs.removeWatcher(path, w)

internal/source/file/file_test.go

@@ -1,7 +1,9 @@
 package file
 
 import (
+	"bytes"
 	"context"
+	"errors"
 	"os"
 	"path/filepath"
 	"slices"
@@ -39,6 +41,89 @@ func TestFileSourceSkipsItsOwnOutput(t *testing.T) {
 	}
 }
 
+// A directory the source cannot read is logged when that starts and when it
+// ends, not on every check: a missing one at info, as it may yet be made,
+// any other failure at warn
+func TestUnreadableDirectoryIsLoggedOncePerChange(t *testing.T) {
+	logger, out := txtLogger(t)
+	dir := filepath.Join(t.TempDir(), "logs")
+	source := &FileSource{config: &config.FileSourceOptions{Directory: dir, Pattern: "*"}, watchers: map[string]*fileWatcher{}, logger: logger}
+	checksAfter := func(err error) {
+		if err != nil {
+			t.Fatal(err)
+		}
+		for range 3 {
+			source.checkTargets()
+		}
+	}
+	checksAfter(nil)
+	checksAfter(os.Mkdir(dir, 0o700))
+	checksAfter(errors.Join(os.Remove(dir), os.WriteFile(dir, nil, 0o600)))
+	if err := logger.Flush(time.Second); err != nil {
+		t.Fatal(err)
+	}
+	lines := slices.Collect(strings.Lines(out.String()))
+	want := [][2]string{{"INFO", "Waiting for directory"}, {"INFO", "Directory readable"}, {"WARN", "Cannot read directory"}}
+	for i, w := range want {
+		if len(lines) != len(want) || !strings.Contains(lines[i], " "+w[0]+" ") || !strings.Contains(lines[i], w[1]) {
+			t.Fatalf("logged:\n%swant %v", out.String(), want)
+		}
+	}
+}
+
+// A file the source cannot open, from its watcher's start or later, is logged
+// as that starts, not on every check, and read once it opens: the watcher goes
+// on
+func TestUnreadableFileIsLoggedOnceAndWaitedFor(t *testing.T) {
+	logger, out := txtLogger(t)
+	dir := filepath.Join(t.TempDir(), "logs")
+	block := func() error { return errors.Join(os.RemoveAll(dir), os.WriteFile(dir, nil, 0o600)) } // logs/a.log cannot open
+	read := make(chan string, 10)
+	w := newFileWatcher(filepath.Join(dir, "a.log"), true, true, func(e core.LogEntry) { read <- e.Message }, logger)
+	ctx, cancel := context.WithCancel(context.Background())
+	done := make(chan error)
+	if err := block(); err != nil {
+		t.Fatal(err)
+	}
+	go func() { done <- w.watch(ctx) }()
+	time.Sleep(4 * core.FileWatcherPollInterval)
+	if err := errors.Join(os.Remove(dir), os.Mkdir(dir, 0o700), os.WriteFile(filepath.Join(dir, "a.log"), []byte("first\n"), 0o600)); err != nil {
+		t.Fatal(err)
+	}
+	select {
+	case <-read:
+	case <-time.After(time.Second):
+		t.Fatal("not read once it opened")
+	}
+	if err := block(); err != nil {
+		t.Fatal(err)
+	}
+	time.Sleep(4 * core.FileWatcherPollInterval)
+	cancel()
+	<-done
+	if err := logger.Flush(time.Second); err != nil {
+		t.Fatal(err)
+	}
+	if strings.Count(out.String(), "\n") != 2 || strings.Count(out.String(), " WARN ") != 2 || strings.Count(out.String(), "Cannot read file") != 2 {
+		t.Fatalf("logged:\n%swant Cannot read file twice", out.String())
+	}
+}
+
+// txtLogger logs txt lines into the buffer it returns, read after Flush
+func txtLogger(t *testing.T) (*log.Logger, *bytes.Buffer) {
+	t.Helper()
+	out := &bytes.Buffer{}
+	logger := log.NewLogger()
+	logger.SetConsoleWriter(out)
+	cfg := log.DefaultConfig()
+	cfg.Format = "txt"
+	if err := logger.ApplyConfig(cfg); err != nil || logger.Start() != nil {
+		t.Fatal(err)
+	}
+	t.Cleanup(func() { logger.Shutdown() })
+	return logger, out
+}
+
 func TestStoppedWatcherReturnsNormally(t *testing.T) {
 	path := filepath.Join(t.TempDir(), "session.jsonl")
 	testutil.WriteFile(t, path, "")

internal/source/file/file_watcher.go

@@ -47,6 +47,7 @@ type fileWatcher struct {
 	entriesRead  atomic.Uint64
 	lastReadTime atomic.Value // time.Time
 	logger       *log.Logger
+	failed       string // the last check's error, "" for none; watch's
 }
 
 // newFileWatcher creates a new watcher for a specific file path.
@@ -67,16 +68,19 @@ func newFileWatcher(directory string, raw, fromStart bool, callback func(core.Lo
 	return w
 }
 
-// watch starts the main monitoring loop for the file
+// watch follows the file until ctx ends or stop: it finds where to start,
+// again each check until the file opens, then reads what the file gains
 func (w *fileWatcher) watch(ctx context.Context) error {
-	if err := w.initPosition(); err != nil {
-		return fmt.Errorf("initPosition failed: %w", err)
-	}
-
 	ticker := time.NewTicker(core.FileWatcherPollInterval)
 	defer ticker.Stop()
 
+	check := w.initPosition
 	for {
+		err := check()
+		if err == nil {
+			check = w.checkFile
+		}
+		w.note(err)
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
@@ -84,14 +88,18 @@ func (w *fileWatcher) watch(ctx context.Context) error {
 			if w.isStopped() {
 				return nil
 			}
-			if err := w.checkFile(); err != nil {
-				// Log error but continue watching
-				w.logger.Warn("msg", "checkFile error", "error", err)
-			}
 		}
 	}
 }
 
+// note logs a check's failure as it starts or changes, not every check; the
+// watcher goes on
+func (w *fileWatcher) note(err error) {
+	if changed(&w.failed, err) && err != nil {
+		w.logger.Warn("msg", "Cannot read file", "component", "file_watcher", "path", w.directory, "error", err)
+	}
+}
+
 // stop signals the watcher to terminate its loop
 func (w *fileWatcher) stop() {
 	w.mu.Lock()
@@ -127,20 +135,12 @@ func (w *fileWatcher) checkFile() error {
 			// File doesn't exist yet, keep watching
 			return nil
 		}
-		w.logger.Error("msg", "Failed to open file for checking",
-			"component", "file_watcher",
-			"directory", w.directory,
-			"error", err)
 		return err
 	}
 	defer file.Close()
 
 	info, err := file.Stat()
 	if err != nil {
-		w.logger.Error("msg", "Failed to stat file",
-			"component", "file_watcher",
-			"directory", w.directory,
-			"error", err)
 		return err
 	}
 
@@ -269,11 +269,6 @@ func (w *fileWatcher) checkFile() error {
 		}
 
 		if err := scanner.Err(); err != nil {
-			w.logger.Error("msg", "Scanner error while reading file",
-				"component", "file_watcher",
-				"directory", w.directory,
-				"position", startPos,
-				"error", err)
 			return err
 		}