logwisp/internal/source/file/file_test.go

package file

import (
	"bytes"
	"context"
	"errors"
	"fmt"
	"os"
	"path/filepath"
	"slices"
	"strings"
	"syscall"
	"testing"
	"time"

	"github.com/lixenwraith/logwisp/internal/config"
	"github.com/lixenwraith/logwisp/internal/core"
	"github.com/lixenwraith/logwisp/internal/testutil"

	"github.com/lixenwraith/log"
)

// A file source never follows the file lw's stdout or stderr is: `lw > out.log`
// in the directory it follows would read its own output back, endlessly
func TestFileSourceSkipsItsOwnOutput(t *testing.T) {
	dir := t.TempDir()
	testutil.WriteFile(t, filepath.Join(dir, "app.log"), "")
	testutil.WriteFile(t, filepath.Join(dir, "out.log"), "")
	own, err := os.Stat(filepath.Join(dir, "out.log"))
	if err != nil {
		t.Fatal(err)
	}
	source := &FileSource{
		config:     &config.FileSourceOptions{Directory: dir, Pattern: "*.log"},
		own:        []os.FileInfo{own},
		ownSkipped: map[string]bool{},
		logger:     log.NewLogger(),
	}
	files, err := source.scanFile()
	if err != nil || len(files) != 1 || filepath.Base(files[0]) != "app.log" {
		t.Fatalf("scanFile = %v, %v; want app.log alone", files, err)
	}
}

// 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, "")
	watcher := newFileWatcher(path, true, true, func(_ core.LogEntry) {}, nil)
	watcher.stop()

	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
	defer cancel()
	if err := watcher.watch(ctx); err != nil {
		t.Fatalf("stopped watcher returned error: %v", err)
	}
}

func TestRemoveWatcherPreservesReplacement(t *testing.T) {
	oldWatcher := &fileWatcher{}
	replacement := &fileWatcher{}
	source := &FileSource{
		watchers: map[string]*fileWatcher{
			"session.jsonl": replacement,
		},
	}

	source.removeWatcher("session.jsonl", oldWatcher)
	if got := source.watchers["session.jsonl"]; got != replacement {
		t.Fatalf("replacement watcher = %p, want %p", got, replacement)
	}

	source.removeWatcher("session.jsonl", replacement)
	if _, exists := source.watchers["session.jsonl"]; exists {
		t.Fatal("finished watcher was not removed")
	}
}

// A line longer than core.MaxLogEntryBytes continues in the next entry, and the
// lines around it are read once
func TestLongLineContinuesInTheNextEntry(t *testing.T) {
	path := filepath.Join(t.TempDir(), "app.log")
	long := strings.Repeat("x", core.MaxLogEntryBytes+10)
	testutil.WriteFile(t, path, "first\n"+long+"\nafter\n")
	var got []string
	w := newFileWatcher(path, true, true, func(e core.LogEntry) { got = append(got, e.Message) }, log.NewLogger())
	for range 2 {
		if err := w.checkFile(); err != nil {
			t.Fatal(err)
		}
	}
	want := []string{"first", long[:core.MaxLogEntryBytes], long[core.MaxLogEntryBytes:], "after"}
	if !slices.Equal(got, want) {
		t.Fatalf("read %d entries, want %d: first, the long line in two, after", len(got), len(want))
	}
}

// A rotated file reappears under its archive name with the same inode. Its
// replacement watcher resumes where the original stopped, so a `from = "start"`
// source does not re-emit every record the file already delivered.
func TestRotatedFileResumesInsteadOfReplaying(t *testing.T) {
	dir := t.TempDir()
	active := filepath.Join(dir, "session.jsonl")
	testutil.WriteFile(t, active, "one\ntwo\n")
	info, err := os.Stat(active)
	if err != nil {
		t.Fatal(err)
	}
	inode := info.Sys().(*syscall.Stat_t).Ino

	archive := filepath.Join(dir, "session_260916_120000.jsonl")
	if err := os.Rename(active, archive); err != nil {
		t.Fatal(err)
	}

	for name, watcher := range map[string]*fileWatcher{
		"still tailing the renamed inode": {inode: inode, position: 8},
		"already moved on from it":        {inode: 99, prevInode: inode, prevPosition: 8},
	} {
		source := &FileSource{watchers: map[string]*fileWatcher{active: watcher}}
		position, ok := source.readPosition(archive)
		if !ok || position != 8 {
			t.Errorf("%s: position = %d, ok = %v, want 8, true", name, position, ok)
		}
	}

	unrelated := &FileSource{watchers: map[string]*fileWatcher{active: {inode: 99}}}
	if _, ok := unrelated.readPosition(archive); ok {
		t.Error("a file no watcher has read was treated as rotated")
	}
}

// lines are log lines stamped with day, from line first up to but not
// including last
func lines(day, first, last int) string {
	var b strings.Builder
	for i := first; i < last; i++ {
		fmt.Fprintf(&b, "Oct %d 00:00:%02d host app[1]: line %d\n", day, i%60, i)
	}
	return b.String()
}

// appendFile adds text to the file's end, as a writer would
func appendFile(t *testing.T, path, text string) {
	t.Helper()
	f, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND, 0)
	if err != nil {
		t.Fatal(err)
	}
	if _, err := f.WriteString(text); err != nil {
		t.Fatal(err)
	}
	if err := f.Close(); err != nil {
		t.Fatal(err)
	}
}

// tailFrom starts a watcher at the file's end; each call of the check it
// returns polls once and gives the messages read
func tailFrom(t *testing.T, path string) func() []string {
	t.Helper()
	var got []string
	w := newFileWatcher(path, true, false, func(e core.LogEntry) { got = append(got, e.Message) }, log.NewLogger())
	if err := w.initPosition(); err != nil {
		t.Fatal(err)
	}
	return func() []string {
		t.Helper()
		got = nil
		if err := w.checkFile(); err != nil {
			t.Fatal(err)
		}
		return got
	}
}

// An edited file is still the file being read, however it is saved and
// wherever lines are deleted or inserted: reading resumes after the newest
// line read that it still holds, and replays nothing
func TestEditedFileResumesAfterTheLastLineRead(t *testing.T) {
	saves := map[string]func(t *testing.T, check func() []string, path, text string){
		"by rename": func(t *testing.T, _ func() []string, path, text string) {
			testutil.WriteFile(t, path+".tmp", text)
			if err := os.Rename(path+".tmp", path); err != nil {
				t.Fatal(err)
			}
		},
		"in place": func(t *testing.T, _ func() []string, path, text string) { testutil.WriteFile(t, path, text) },
		"in place, polled while empty": func(t *testing.T, check func() []string, path, text string) {
			testutil.WriteFile(t, path, "")
			if got := check(); len(got) != 0 {
				t.Fatalf("read %q from the emptied file", got)
			}
			testutil.WriteFile(t, path, text)
		},
		"in place, polled partway": func(t *testing.T, check func() []string, path, text string) {
			testutil.WriteFile(t, path, text[:len(text)/2])
			if got := check(); len(got) != 0 {
				t.Fatalf("read %q from the file half written", got)
			}
			testutil.WriteFile(t, path, text)
		},
	}
	for name, save := range saves {
		t.Run(name, func(t *testing.T) {
			path := filepath.Join(t.TempDir(), "messages")
			base := lines(14, 0, 20)
			testutil.WriteFile(t, path, base)
			check := tailFrom(t, path)
			steps := []struct {
				text string
				want []string
			}{
				{base + "ssh in\n", []string{"ssh in"}},
				{base, nil}, // the line read last, deleted
				{base + "after\n", []string{"after"}},
				{lines(14, 0, 15) + lines(14, 16, 20) + "after\nmore\n", []string{"more"}}, // a line before it deleted
				{lines(14, 0, 5) + "inserted\n" + lines(14, 5, 15) + lines(14, 16, 20) + "after\nmore\nagain\n", []string{"again"}},
				{lines(14, 10, 15) + lines(14, 16, 20) + "after\nmore\nagain\nlast\n", []string{"last"}},   // the top trimmed
				{lines(14, 10, 15) + lines(14, 16, 20) + "after\nmore\nagain\nfinal\n", []string{"final"}}, // the line read last replaced
				{"final\nend\n", []string{"end"}}, // trimmed down to the line read last
			}
			for i, step := range steps {
				save(t, check, path, step.text)
				// a missing line read last holds the file for one check, until it settles
				if got := append(check(), check()...); !slices.Equal(got, step.want) {
					t.Fatalf("save %d read %q, want %q", i+1, got, step.want)
				}
			}
		})
	}
}

// A file that starts anew is a rotation: it is read from its start, after the
// entry saying so and once it settles, however it was replaced, whatever its
// size, and wherever in a line the last read ended
func TestRotatedFileIsReadFromItsStart(t *testing.T) {
	fresh := lines(15, 0, 3)
	rotations := map[string]func(t *testing.T, check func() []string, path string){
		"truncated and written again": func(t *testing.T, _ func() []string, path string) { testutil.WriteFile(t, path, fresh) },
		"renamed away and made anew": func(t *testing.T, _ func() []string, path string) {
			if err := os.Rename(path, path+".1"); err != nil {
				t.Fatal(err)
			}
			testutil.WriteFile(t, path, fresh)
		},
		"made anew past the position read": func(t *testing.T, _ func() []string, path string) {
			testutil.WriteFile(t, path, fresh+lines(15, 3, 60))
		},
		"emptied, polled, then written": func(t *testing.T, check func() []string, path string) {
			testutil.WriteFile(t, path, "")
			if got := check(); len(got) != 0 {
				t.Fatalf("read %q from the emptied file", got)
			}
			testutil.WriteFile(t, path, fresh)
		},
		// a block-buffered writer leaves a line half written: no mark, though
		// the new lines start as it does
		"after a line read half written": func(t *testing.T, check func() []string, path string) {
			appendFile(t, path, "Oct 1")
			check()
			testutil.WriteFile(t, path, fresh)
		},
		// copytruncate under a writer that does not append: it goes on at its
		// offset, past a hole of NULs, which is no entry
		"truncated under a writer at its offset": func(t *testing.T, _ func() []string, path string) {
			testutil.WriteFile(t, path, strings.Repeat("\x00", len(lines(14, 0, 20)))+fresh)
		},
	}
	for name, rotate := range rotations {
		t.Run(name, func(t *testing.T) {
			path := filepath.Join(t.TempDir(), "messages")
			testutil.WriteFile(t, path, lines(14, 0, 20))
			check := tailFrom(t, path)
			rotate(t, check, path)
			got := append(check(), check()...)
			want := slices.Collect(strings.Lines(fresh))
			if len(got) < len(want)+1 || !strings.HasPrefix(got[0], "Log rotation detected (#1)") {
				t.Fatalf("read %q, want the rotation entry, then the new file from its start", got)
			}
			for i, line := range want {
				if got[i+1] != strings.TrimSuffix(line, "\n") {
					t.Fatalf("read %q, want the new file from its start", got)
				}
			}
		})
	}
}

// readTo answers only for files the watcher has read: never the inode an
// editor's save freed, and while a check holds a replaced file, the one renamed
// away, not its replacement
func TestReadToAnswersOnlyForFilesRead(t *testing.T) {
	path := filepath.Join(t.TempDir(), "messages")
	inode := func(name string) uint64 {
		info, err := os.Stat(name)
		if err != nil {
			t.Fatal(err)
		}
		return inodeOf(info)
	}
	text := lines(14, 0, 20)
	testutil.WriteFile(t, path, text)
	w := newFileWatcher(path, true, false, func(core.LogEntry) {}, log.NewLogger())
	if err := w.initPosition(); err != nil {
		t.Fatal(err)
	}

	freed := inode(path)
	text += "edited\n"
	testutil.WriteFile(t, path+".tmp", text)
	if err := errors.Join(os.Rename(path+".tmp", path), w.checkFile()); err != nil {
		t.Fatal(err)
	}
	if _, _, ok := w.readTo(freed); ok {
		t.Error("the inode an editor's save freed is taken for an archive")
	}

	archive := path + ".1"
	if err := os.Rename(path, archive); err != nil {
		t.Fatal(err)
	}
	testutil.WriteFile(t, path, "")
	if err := w.checkFile(); err != nil {
		t.Fatal(err)
	}
	if position, _, ok := w.readTo(inode(archive)); !ok || position != int64(len(text)) {
		t.Errorf("held: the renamed file read to %d, %v; want %d, true", position, ok, len(text))
	}
	if _, _, ok := w.readTo(inode(path)); ok {
		t.Error("held: the replacement is answered for before it is judged")
	}
	if err := w.checkFile(); err != nil {
		t.Fatal(err)
	}
	if position, _, ok := w.readTo(inode(archive)); !ok || position != int64(len(text)) {
		t.Errorf("judged: the renamed file read to %d, %v; want %d, true", position, ok, len(text))
	}
}

// A rotation shifts archives along their names (app.log to app.log.1, that to
// app.log.2): each watcher finds the file the one before it read and goes on
// from where that one got, so nothing is replayed and what it left is read
// once. An inode reused, claimed by a watcher of a deleted file, is not it.
func TestShiftedArchiveResumesWhereItWasRead(t *testing.T) {
	for name, order := range map[string][]int{"the archive's watcher first": {1, 0}, "the file's watcher first": {0, 1}} {
		t.Run(name, func(t *testing.T) {
			dir := t.TempDir()
			paths := []string{filepath.Join(dir, "app.log"), filepath.Join(dir, "app.log.1"), filepath.Join(dir, "app.log.2")}
			testutil.WriteFile(t, paths[0], lines(15, 0, 20))
			testutil.WriteFile(t, paths[1], lines(14, 0, 20))
			var got []string
			source := &FileSource{watchers: map[string]*fileWatcher{}}
			watchers := make([]*fileWatcher, 2)
			for i := range watchers {
				w := newFileWatcher(paths[i], true, false, func(e core.LogEntry) { got = append(got, e.Message) }, log.NewLogger())
				w.others = source.othersOf(w)
				if err := w.initPosition(); err != nil {
					t.Fatal(err)
				}
				source.watchers[paths[i]], watchers[i] = w, w
			}

			appendFile(t, paths[0], "unread\n")
			for i := 1; i >= 0; i-- {
				if err := os.Rename(paths[i], paths[i+1]); err != nil {
					t.Fatal(err)
				}
			}
			testutil.WriteFile(t, paths[0], "fresh\n")
			info, err := os.Stat(paths[0])
			if err != nil {
				t.Fatal(err)
			}
			source.watchers["deleted"] = &fileWatcher{inode: inodeOf(info), position: 3, tail: []byte("ab\n")}
			source.watchers["deleted too"] = &fileWatcher{prevInode: watchers[0].inode, prevPosition: 3, prevTail: []byte("ab\n")}
			for range 2 {
				for _, i := range order {
					if err := watchers[i].checkFile(); err != nil {
						t.Fatal(err)
					}
				}
			}
			want := []string{"Log rotation detected (#1): the file starts anew", "fresh", "unread"}
			if slices.Sort(got); !slices.Equal(got, want) {
				t.Errorf("read %q, want %q", got, want)
			}
			if position, ok := source.readPosition(paths[2]); !ok || position != int64(len(lines(14, 0, 20))) {
				t.Errorf("app.log.2 read to %d, %v; want %d, true", position, ok, len(lines(14, 0, 20)))
			}
		})
	}
}