diff --git a/docs/cli.md b/docs/cli.md index 292f3cd9..1f715405 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -625,7 +625,10 @@ Service log files are appended across runs. `--run` reads only one run's own par `log_offset` to where the next run of that service started writing, so a later generation's lines — including the error it died on — are not reported as this run's. A run that is still writing owns everything after its start; two runs that overlap in time write interleaved bytes, and their parts -cannot be told apart. `--run current` selects the service's current run, and any other value is an +cannot be told apart. A run that has ended owns only the bytes already in the file: when no later +generation has recorded where it took over — the newest finished run — its part ends at the end of +the file as it is when read, so following it prints and returns instead of waiting for a generation +that has not started yet. `--run current` selects the service's current run, and any other value is an exact historical `run_id` from `status --json`. `current` prefers a process that is still running and only falls back to the most recently finished one when there is none. Following a run that has ended prints its lines and stops: nothing arrives for it afterwards. `--run` accepts only service names, diff --git a/docs/cli.zh.md b/docs/cli.zh.md index ef4e68cd..f18b5e32 100644 --- a/docs/cli.zh.md +++ b/docs/cli.zh.md @@ -515,7 +515,9 @@ daemon 是账本的唯一写者:它在扫描到清单时记录身份,重启 服务日志文件跨多次运行追加。`--run` 只读该文件里这一次运行自己的那一段:从 `log_offset` 到 同一服务下一次运行开始写入的位置,因此后续运行的行——包括它崩溃时那条错误——不会被当成这次 运行输出的一部分。仍在运行的那次运行拥有起点之后的全部内容;两次运行在时间上重叠时,它们的 -字节交织在同一个文件里,无法区分。`--run current` 选该服务当前这次运行,其他值则是 +字节交织在同一个文件里,无法区分。已经结束的那次运行只拥有文件里已写入的字节:后续运行还没有 +记录接管位置时(最近一次结束的运行就是这种情况),它的这一段止于读取时的文件末尾,跟随它会 +打印后返回,而不是等待一次尚未开始的运行。`--run current` 选该服务当前这次运行,其他值则是 `status --json` 里的精确 `run_id`。`current` 优先选仍在运行的进程,没有时才选最近结束的一次。 跟随一次已经结束的运行会打印它的行然后停止:之后不会再有属于它的输出。`--run` 只接受服务名, 不能和 `--ip` 同时使用;它需要 daemon,daemon 不可用时返回 `daemon_unavailable`。旧运行记录 diff --git a/engine/internal/cmd/logs.go b/engine/internal/cmd/logs.go index 3c678f21..969336b0 100644 --- a/engine/internal/cmd/logs.go +++ b/engine/internal/cmd/logs.go @@ -310,9 +310,10 @@ func requireLogFile(path string) error { return nil } -// streamFileLogsFrom follows one run's range of the file. A range with an end -// belongs to a run that has finished, so it is printed and the read stops: -// nothing that arrives afterwards can belong to that run. +// streamFileLogsFrom follows one run's range of the file. A range that cannot +// grow belongs to a run that has finished — either its end byte is recorded, or +// the run has ended and the file as it is now is its end — so it is printed and +// the read stops: nothing that arrives afterwards can belong to that run. func streamFileLogsFrom(ctx context.Context, path string, rng logRange, asJSON bool, lines int, meta logMetadata) error { if err := requireLogFile(path); err != nil { return err diff --git a/engine/internal/cmd/logs_run.go b/engine/internal/cmd/logs_run.go index 30bc11c7..4d9d26d1 100644 --- a/engine/internal/cmd/logs_run.go +++ b/engine/internal/cmd/logs_run.go @@ -60,35 +60,46 @@ func logsFromRun(ctx context.Context, c *client.Client, target, selector string) } // logRange is the part of a log file one read covers, in bytes: [start, end). -// A whole-file read is a range that starts at zero. end < 0 means the range -// has no known end: the run that owns it is still writing, so the end of the -// file is its end for as long as the read lasts. +// A whole-file read is a range that starts at zero. end < 0 means no byte +// position was recorded where the range stops; ended then says whether the run +// that owns it has stopped writing. A run that is still writing owns everything +// after its start, so the end of the file is its end for as long as the read +// lasts; a run that has ended owns only what is already in the file. type logRange struct { start int64 end int64 + // ended says the run that owns this range has exited. Nothing it wrote can + // appear after the file as it is when read, so the range cannot grow a line + // even when no later generation recorded where it took over. + ended bool } // bounded says the range's last byte is already written: a finished run cannot -// grow another line, so following it is a read, not a wait. -func (r logRange) bounded() bool { return r.end >= 0 } +// grow another line, so following it is a read, not a wait. The one range that +// is not bounded belongs to a run that is still writing. +func (r logRange) bounded() bool { return r.end >= 0 || r.ended } // runLogRange is where one run's bytes end in the file its service appends to // across generations. The file is a single stream of bytes and only each run's -// start was recorded, so the end is where the next generation took over: a run -// that started after this one ended began writing exactly where this one -// stopped. Without such a run the range stays open, which is the truth for the -// newest run and for one that is still writing; closing it at the end of the -// file instead would report a later run's lines — and the error it died on — -// as this run's. +// start was recorded, so the exact end is where the next generation took over: +// a run that started after this one ended began writing exactly where this one +// stopped. Without such a run — the newest finished one is the usual case — the +// range still ends at the end of the file, because a run that has exited cannot +// append. Leaving it open instead would make a follow wait for bytes that will +// belong to a generation not yet started, under this run's name. func runLogRange(rec rpc.RunRecord, records []rpc.RunRecord) logRange { rng := logRange{start: *rec.LogOffset, end: -1} if rec.Status != "exited" { return rng } + // From here the run has ended: whatever it wrote is already in the file, so + // a read can stop at the file's end even when the loop below finds no exact + // byte to stop at. + rng.ended = true endedAt := parseRunTime(rec.ExitedAt) if endedAt.IsZero() { // Without the moment this run ended, no later run can be shown to have - // started after it; an open range is the honest answer. + // started after it; the end of the file is the best bound there is. return rng } for _, other := range records { @@ -266,6 +277,12 @@ func readRunLines(path string, rng logRange) ([]string, []int64, bool, error) { } size := info.Size() start, end := rng.start, rng.end + if end < 0 && rng.ended { + // The run has ended, so the file as it is now is where its range stops. + // Limiting the read to the size observed here keeps out bytes a later + // generation appends while this read is in progress. + end = size + } unknown := false // A rotation invalidates every recorded byte position: the start lies past // the end of the file, or the range ends behind its own start because a diff --git a/engine/internal/cmd/logs_run_test.go b/engine/internal/cmd/logs_run_test.go index 37a25776..20871b9e 100644 --- a/engine/internal/cmd/logs_run_test.go +++ b/engine/internal/cmd/logs_run_test.go @@ -7,6 +7,7 @@ import ( "path/filepath" "strings" "testing" + "time" "github.com/sheathedsharp/option-berth/engine/internal/daemon/rpc" ) @@ -233,10 +234,10 @@ func TestRunLogRangeEndsWhereTheNextGenerationStarted(t *testing.T) { LogPath: "/logs/api.log", StartedAt: "2026-11-01T10:08:00Z", LogOffset: int64Ptr(90)} records := []rpc.RunRecord{live, second, first} - if got := runLogRange(first, records); got != (logRange{start: 0, end: 40}) { + if got := runLogRange(first, records); got != (logRange{start: 0, end: 40, ended: true}) { t.Fatalf("first run range = %+v, want [0,40)", got) } - if got := runLogRange(second, records); got != (logRange{start: 40, end: 90}) { + if got := runLogRange(second, records); got != (logRange{start: 40, end: 90, ended: true}) { t.Fatalf("second run range = %+v, want [40,90)", got) } // The run that is still writing owns everything after its own start. @@ -262,8 +263,25 @@ func TestRunLogRangeIgnoresRunsThatDidNotWriteAfterThisOne(t *testing.T) { LogPath: "/logs/api.log", StartedAt: "2026-11-01T10:07:00Z", ExitedAt: "2026-11-01T10:08:00Z"} records := []rpc.RunRecord{first, overlapping, elsewhere, unrecorded} - if got := runLogRange(first, records); got != (logRange{start: 0, end: -1}) { - t.Fatalf("range = %+v, want [0,EOF): nothing recorded where this run's bytes end", got) + if got := runLogRange(first, records); got != (logRange{start: 0, end: -1, ended: true}) { + t.Fatalf("range = %+v, want an ended range: nothing recorded where this run's bytes end, but it cannot write more", got) + } +} + +// The newest finished run has no successor to record where it took over. It has +// ended all the same, so its range stops at the file as it is when read: a +// follow reads and returns instead of waiting for a generation that does not +// exist yet. +func TestRunLogRangeOfANewestFinishedRunEndsAtTheFile(t *testing.T) { + ended := rpc.RunRecord{ID: "r1", Group: "shop", Name: "api", Status: "exited", + LogPath: "/logs/api.log", StartedAt: "2026-11-01T10:00:00Z", ExitedAt: "2026-11-01T10:02:00Z", + LogOffset: int64Ptr(120)} + got := runLogRange(ended, []rpc.RunRecord{ended}) + if !got.bounded() { + t.Fatalf("range = %+v, want a bound: the run has ended and cannot append", got) + } + if got.start != 120 || got.end != -1 { + t.Fatalf("range = %+v, want the run's own bytes up to the file end", got) } } @@ -308,6 +326,47 @@ func TestFollowOfAFinishedRunPrintsItsLinesAndStops(t *testing.T) { } } +// The same follow for a run that has ended with no successor recorded yet — the +// newest finished run. The file is still there to grow when the next generation +// starts, so the read must stop at the file rather than follow it: bytes that +// arrive afterwards belong to whichever run writes them, not to this one. +func TestFollowOfAFinishedRunWithoutASuccessorReturns(t *testing.T) { + path := filepath.Join(t.TempDir(), "api.log") + if err := os.WriteFile(path, []byte("booting\nlistening on 3000\n"), 0o600); err != nil { + t.Fatal(err) + } + ended := rpc.RunRecord{ID: "r1", Group: "shop", Name: "api", Status: "exited", + LogPath: path, StartedAt: "2026-11-01T10:00:00Z", ExitedAt: "2026-11-01T10:02:00Z", + LogOffset: int64Ptr(0)} + rng := runLogRange(ended, []rpc.RunRecord{ended}) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + followed := make(chan error, 1) + done := make(chan struct{}) + out := captureStdout(t, func() { + go func() { + defer close(done) + followed <- streamFileLogsFrom(ctx, path, rng, false, 10, logMetadata{Service: "api", RunID: "r1"}) + }() + select { + case <-done: + case <-time.After(5 * time.Second): + // The follow had no end and started waiting for a future run's + // bytes: cancel it so the test can report it instead of hanging. + cancel() + <-done + t.Error("following a run that has ended did not return") + } + }) + if err := <-followed; err != nil && !t.Failed() { + t.Fatal(err) + } + if !t.Failed() && !strings.Contains(out, "listening on 3000") { + t.Fatalf("output = %q, want the run's lines before returning", out) + } +} + func TestSelectRunForLogsPicksTheNewestRun(t *testing.T) { records := []rpc.RunRecord{ {ID: "old", Group: "shop", Name: "api", StartedAt: "2026-10-31T09:00:00Z", Status: "exited"},