diff --git a/CHANGELOG.md b/CHANGELOG.md index d780bfc..4d09362 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,18 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version ## [Unreleased] +### Fixed + +- **A log rotated while the panel was down is read to its end.** On start, + a saved place in a file that had been rotated meant "start on the new + file", and what Postfix wrote between the panel's stop and the rotation - + deliveries, refusals, deferrals - was never read. The tailer now reads the + rotated file (`mail.log.1`) from the saved place to its end first; when + that file is not the one the place belongs to (rotated twice), it says so + in the log, with the time from which nothing was read. The log's + fingerprint now includes the file's inode, so two files that begin alike + are still told apart (audit 2026-10-12, stage 2b). + ## [2.5.0] - 2026-10-14 Stages 1 and 2 of the 2026-10-12 audit: mail the delivery log showed wrong, diff --git a/docs/audit-2026-10-12.md b/docs/audit-2026-10-12.md index 1b09e53..9f32e75 100644 --- a/docs/audit-2026-10-12.md +++ b/docs/audit-2026-10-12.md @@ -736,7 +736,7 @@ stage follows as a cut of its own, with its own reviews. Five of the six change one thing, the tailer and the state it saves, and are done in this order - each stands on the one before. -- [ ] **A log rotated while the panel was down is read to its end** (owner, +- [x] **A log rotated while the panel was down is read to its end** (owner, 2026-10-13; the Not done list of from-header-binding had it as "deferrals are lost", and it is wider). At start, a saved offset whose fingerprint is not the current file's means "start on the new file" diff --git a/docs/roadmap.md b/docs/roadmap.md index b5635b0..6f0caa6 100644 --- a/docs/roadmap.md +++ b/docs/roadmap.md @@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md). | from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) | | panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) | | schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) | -| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 22/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | +| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 23/62 | [audit-2026-10-12.md](audit-2026-10-12.md) | **Recommended order** (not binding; owner, 2026-10-09: feature order follows development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and diff --git a/internal/logtail/fileid_other.go b/internal/logtail/fileid_other.go new file mode 100644 index 0000000..7e02ca0 --- /dev/null +++ b/internal/logtail/fileid_other.go @@ -0,0 +1,9 @@ +//go:build !unix + +package logtail + +import "os" + +// fileID is empty where the system has no inode to give (the panel runs on +// Linux; this keeps the package building elsewhere for its tests). +func fileID(*os.File) string { return "" } diff --git a/internal/logtail/fileid_unix.go b/internal/logtail/fileid_unix.go new file mode 100644 index 0000000..34968d5 --- /dev/null +++ b/internal/logtail/fileid_unix.go @@ -0,0 +1,24 @@ +//go:build unix + +package logtail + +import ( + "fmt" + "os" + "syscall" +) + +// fileID names the file itself - device and inode - which a rename keeps and +// a new file does not share. It is part of the log's fingerprint, so two log +// files whose first bytes happen to match are still told apart. +func fileID(f *os.File) string { + info, err := f.Stat() + if err != nil { + return "" + } + st, ok := info.Sys().(*syscall.Stat_t) + if !ok { + return "" + } + return fmt.Sprintf("%d.%d", st.Dev, st.Ino) +} diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 9c80e36..38b9e9e 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -606,6 +606,10 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ log.Printf("log-tailer: seek %s: %v", path, err) } r.Reset(f) // the reader buffered from the pre-seek position + // Rotated while the panel was down: the end of the old file first. + if tr.readRotated(handle) { + flush() + } defer func() { if f != nil { f.Close() diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index f03b02d..bf2c4ef 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -815,3 +815,79 @@ func TestSplitTimestamp(t *testing.T) { }) } } + +// A log rotated while the panel was down is read to its end before the new +// one: what Postfix wrote between the stop and the rotation is in mail.log.1 +// (audit 2026-10-12, stage 2b). Both halves are read, once each. +func TestALogRotatedWhileDownIsReadToItsEnd(t *testing.T) { + old := pollInterval + pollInterval = 10 * time.Millisecond + t.Cleanup(func() { pollInterval = old }) + + dir := t.TempDir() + path := filepath.Join(dir, "mail.log") + seed := strings.Repeat("host postfix/qmgr[1]: seed line, not a delivery\n", 20) + if err := os.WriteFile(path, []byte(seed), 0o644); err != nil { + t.Fatal(err) + } + cs := &captureStore{} + stop := startRun(t, path, cs) + appendLine(t, path, "host postfix/smtp[1]: Q1: to=, relay=x, dsn=2.0.0, status=sent (ok)") + waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") }) + stop() + + // Down: Postfix writes, then logrotate renames and creates, and Postfix + // goes on in the new file. + appendLine(t, path, "host postfix/smtp[1]: Q2: to=, relay=x, dsn=2.0.0, status=sent (ok)") + if err := os.Rename(path, path+".1"); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path, []byte(strings.Repeat("host postfix/qmgr[1]: the new log\n", 20)+ + "host postfix/smtp[1]: Q3: to=, relay=x, dsn=5.1.1, status=bounced (nope)\n"), 0o644); err != nil { + t.Fatal(err) + } + + cs.reset() + stop = startRun(t, path, cs) + waitFor(t, func() bool { + got := cs.snapshot() + return contains(got, "Q2|b@example.net|sent") && contains(got, "Q3|c@example.net|bounced") + }) + stop() + n := 0 + for _, c := range cs.snapshot() { + if strings.HasPrefix(c, "Q1|") { + t.Errorf("Q1 was read again: %s", c) + } + if strings.HasPrefix(c, "Q2|") { + n++ + } + } + if n != 1 { + t.Errorf("Q2 read %d times, want once", n) + } +} + +// A mail.log.1 that is not the file the saved place belongs to is not read +// from that place: the new file is read from its start and the gap is said. +func TestARotatedLogThatIsNotTheSavedOneIsNotRead(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "mail.log") + if err := os.WriteFile(path+".1", []byte(strings.Repeat("host postfix/qmgr[1]: another file altogether\n", 20)+ + "host postfix/smtp[1]: QX: to=, relay=x, dsn=2.0.0, status=sent (ok)\n"), 0o644); err != nil { + t.Fatal(err) + } + tr := &tracker{path: path, behind: true, prev: store.LogtailState{Fingerprint: "not-this-one", Offset: 10}} + var read []string + if tr.readRotated(func(l string) { read = append(read, l) }) || len(read) != 0 { + t.Fatalf("read %d lines of a rotated file that is not the saved one", len(read)) + } +} + +// A fingerprint saved before it carried the file's identity still matches the +// file by its hash. +func TestSameLogAcceptsAFingerprintOfBefore(t *testing.T) { + if !sameLog("abc", "abc:1.2") || !sameLog("abc:1.2", "abc:1.2") || sameLog("abc:1.2", "abc:1.3") || sameLog("", "abc") { + t.Fatal("sameLog") + } +} diff --git a/internal/logtail/offset.go b/internal/logtail/offset.go index 3448b7a..8e494f7 100644 --- a/internal/logtail/offset.go +++ b/internal/logtail/offset.go @@ -1,12 +1,15 @@ package logtail import ( + "bufio" "crypto/sha256" "encoding/hex" "errors" + "fmt" "io" "log" "os" + "strings" "time" "github.com/mixeme/selfpost/internal/store" @@ -38,6 +41,11 @@ type tracker struct { fp string // fingerprint of the file currently open ("" if too short) saved int64 // last offset written to the store lastSave time.Time + + // behind is set by resume when the saved place belongs to a file that is + // no longer the log - rotated while the panel was down; prev is that place. + behind bool + prev store.LogtailState } // resume returns the byte offset the tailer should start reading f at, having @@ -68,7 +76,7 @@ func (t *tracker) resume(f *os.File) int64 { case !ok: t.saved = size return size - case prev.Fingerprint != "" && prev.Fingerprint == t.fp && prev.Offset <= size: + case prev.Fingerprint != "" && sameLog(prev.Fingerprint, t.fp) && prev.Offset <= size: t.saved = prev.Offset if prev.Offset < size { log.Printf("log-tailer: resuming %s at offset %d (%d bytes to catch up)", @@ -78,10 +86,74 @@ func (t *tracker) resume(f *os.File) int64 { default: log.Printf("log-tailer: %s changed while the panel was down; reading from the start", t.path) t.saved = 0 + t.behind, t.prev = prev.Fingerprint != "", prev return 0 } } +// readRotated reads, when the log was rotated while the panel was down, the +// rest of the file the saved place belongs to: logrotate renamed it to +// mail.log.1 (delaycompress leaves it plain), and what Postfix wrote there +// between the panel's stop and the rotation - deliveries, refusals, deferrals - +// was otherwise never read (audit 2026-10-12, stage 2b). It is read from the +// saved offset to its end, line by line through handle, before the new file +// is read from its start. A mail.log.1 that is not that file - the log +// rotated more than once, or the file is gone - is said in the log, with the +// time from which nothing was read. It reports whether it read anything. +func (t *tracker) readRotated(handle func(string)) bool { + if !t.behind { + return false + } + t.behind = false + rotated := t.path + ".1" + lost := func(why string) { + log.Printf("log-tailer: %s; what was written to %s from %s until it was rotated was not read", + why, t.path, t.prev.UpdatedAt.UTC().Format(time.RFC3339)) + } + f, err := os.Open(rotated) + if err != nil { + lost(fmt.Sprintf("%s cannot be opened (%v)", rotated, err)) + return false + } + defer f.Close() + size, err := fileSize(f) + if err != nil || !sameLog(t.prev.Fingerprint, fingerprintOf(f)) || t.prev.Offset > size { + lost(fmt.Sprintf("%s is not the file the saved place belongs to (rotated more than once while the panel was down?)", rotated)) + return false + } + if _, err := f.Seek(t.prev.Offset, io.SeekStart); err != nil { + lost(fmt.Sprintf("seek %s: %v", rotated, err)) + return false + } + r := bufio.NewReader(f) + for { + line, err := r.ReadString('\n') + if line != "" { + handle(strings.TrimRight(line, "\r\n")) + } + if err != nil { + break + } + } + log.Printf("log-tailer: read %s from offset %d to its end (%d bytes) before the new %s", + rotated, t.prev.Offset, size-t.prev.Offset, t.path) + return true +} + +// sameLog says whether a saved fingerprint is the current file's. One saved +// before the fingerprint carried the file's identity is its hash alone, and is +// compared with the hash. +func sameLog(saved, current string) bool { + if saved == current { + return true + } + if !strings.Contains(saved, ":") { + hash, _, _ := strings.Cut(current, ":") + return saved != "" && saved == hash + } + return false +} + // adopt re-fingerprints after the follow loop switched to a rotated-in file and // persists the fresh start immediately, so a restart right after a rotation // does not resume at the old file's offset. @@ -113,9 +185,11 @@ func (t *tracker) record(f *os.File, offset int64, force bool) { t.lastSave = time.Now() } -// fingerprintOf hashes the head of the file. It returns "" for a file too short -// to identify — the head would still change as Postfix appends, so such a -// fingerprint could not be compared meaningfully on the next start. +// fingerprintOf hashes the head of the file and adds the file's identity +// (device and inode, where there is one): two log files whose first bytes +// match are still two files. It returns "" for a file too short to identify — +// the head would still change as Postfix appends, so such a fingerprint could +// not be compared meaningfully on the next start. func fingerprintOf(f *os.File) string { buf := make([]byte, fingerprintSize) n, err := f.ReadAt(buf, 0) @@ -127,7 +201,11 @@ func fingerprintOf(f *os.File) string { return "" } sum := sha256.Sum256(buf) - return hex.EncodeToString(sum[:]) + fp := hex.EncodeToString(sum[:]) + if id := fileID(f); id != "" { + fp += ":" + id + } + return fp } func fileSize(f *os.File) (int64, error) { diff --git a/internal/store/logtail.go b/internal/store/logtail.go index e9d1fc8..68a3a7e 100644 --- a/internal/store/logtail.go +++ b/internal/store/logtail.go @@ -14,17 +14,23 @@ import ( type LogtailState struct { Fingerprint string Offset int64 + // UpdatedAt is when the position was saved; read back only (zero on save). + UpdatedAt time.Time } // LogtailState returns the stored read position for path. ok is false the first // time a path is followed (nothing persisted yet), which the tailer treats as // "start at the end". func (s *Store) LogtailState(path string) (LogtailState, bool, error) { - var st LogtailState + var ( + st LogtailState + updated string + ) err := s.db.QueryRow( - `SELECT fingerprint, read_offset FROM logtail_state WHERE path = ?`, + `SELECT fingerprint, read_offset, updated_at FROM logtail_state WHERE path = ?`, path, - ).Scan(&st.Fingerprint, &st.Offset) + ).Scan(&st.Fingerprint, &st.Offset, &updated) + st.UpdatedAt, _ = time.Parse(time.RFC3339, updated) if errors.Is(err, sql.ErrNoRows) { return LogtailState{}, false, nil }