From 872ba702cb87bcb261296de369c53f4ce8da1ccb Mon Sep 17 00:00:00 2001 From: "Snow Lee (Sungwon)" Date: Thu, 30 Jul 2026 21:49:23 +0900 Subject: [PATCH] =?UTF-8?q?fix(log):=20bdrive=20log=20reads=20as=20a=20tim?= =?UTF-8?q?eline=20=E2=80=94=20newest=20first=20by=20edit=20time=20(#BEA-4?= =?UTF-8?q?0)=20(#90)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `bdrive log` sorted by the lamport clock, so the wall-clock stamps it prints came out non-monotonic — two 06:09:24 rows above a 06:10:00 row. And every op of one scan is stamped with that scan's commit time, so a 22-file agent run collapsed onto a single stamp. Neither is readable as a timeline, which is the whole job of the command. Two display-only changes: - `journal.Op` gains `Mtime` (`omitzero`, so old journals and old binaries are unaffected), populated on put ops from the `os.FileInfo` the scan already holds. Deletes and conflict copies keep their commit time. - `syncer.DisplayTime` / `SortForDisplay` order by the timestamp that is actually printed, ties broken by reversed `journal.Less`. `bdrive log` sorts and *then* truncates, so `-n 25` is the 25 newest by that stamp. `journal.Less`, `Sort`, and `Replay` are untouched — replay order is the convergence contract, so the sort lives in `syncer`, not in `journal`. `LogEntries` also keeps returning causal order because `bdrive restore` walks it to find a file's previous version. Co-authored-by: Claude Opus 5 (1M context) --- README.md | 2 +- architecture/cli-sync.md | 4 +- cmd/bdrive/cmds.go | 15 ++- cmd/bdrive/log_test.go | 126 +++++++++++++++++++ internal/journal/journal.go | 4 + internal/journal/journal_test.go | 35 ++++++ internal/syncer/syncer.go | 26 ++++ internal/syncer/syncer_test.go | 134 +++++++++++++++++++++ web/docs/src/content/docs/reference/cli.md | 2 +- 9 files changed, 341 insertions(+), 7 deletions(-) create mode 100644 cmd/bdrive/log_test.go diff --git a/README.md b/README.md index 82203cb..c67a335 100644 --- a/README.md +++ b/README.md @@ -236,7 +236,7 @@ hub's own storage, never something a syncing client points at directly: | `bdrive hooks [install\|uninstall]` | Register turn-boundary sync hooks in each agent platform's user config (Claude Code, Codex, Gemini CLI, Hermes) — pull each turn, push after edits, session-note stamping, agent-read tracking. Once per machine, covering every session; run automatically by `bdrive init`; idempotent (`--agent` overrides detection) | | `bdrive read-log [folder]` | Hook plumbing: queue agent file reads from a hook event (JSON on stdin) for the hub's read heatmap — native reads, grep matches, and files named in shell commands; drained on the next sync. Registered by `bdrive hooks install` | | `bdrive status [folder]` | Projects, daemon state, pending changes | -| `bdrive log [folder] [-p path] [-n N]` | Change history: account, device, time, file | +| `bdrive log [folder] [-p path] [-n N]` | Change history: account, device, time, file — newest first by the time shown, which is when the file was written (ops recorded before this was tracked, and deletes, show their sync time instead) | | `bdrive restore [version]` | Put an earlier version of a file back, as a new change (`--list` shows the versions; no version = the previous one). Nothing is erased and it syncs everywhere like any edit. A file that was *created* can't be un-created yet | | `bdrive export [folder]` | Export the whole project — every device's journal, all blobs, full history — from its hub to a portable `.tar.gz` (`-o` names the file) | | `bdrive import ` | Import an export archive as a new project on the hub you're logged into (`--name` overrides); history and authorship carry over. Move projects between hubs — cloud → self-hosted or back — with `export` + `login` + `import` | diff --git a/architecture/cli-sync.md b/architecture/cli-sync.md index a4368d0..4a89660 100644 --- a/architecture/cli-sync.md +++ b/architecture/cli-sync.md @@ -24,6 +24,7 @@ classDiagram +Cycle(ctx) Result +Restore(ctx, path, sha) error } + note for Session "syncer also exposes LogEntries (causal order, what bdrive restore walks) plus DisplayTime / SortForDisplay — the newest-first-by-clock order bdrive log prints" note for Session "Restore writes a historical blob back into the working folder as an ordinary edit (fetching it from the hub when this device never held it) — the next Cycle journals it like any other change; it takes no lock and appends to no journal itself" note for Session "internal/syncer — scan → commit local ops → pull peer journals → preserve conflicts → refresh rules → prune → materialize → push blobs then own journal" note for Session "Prune (bdrive forget / sync --prune, never the daemon) journals a delete for every replayed path the SHARED ignore rules exclude — the include scope is per-device and must never prune it" @@ -76,8 +77,9 @@ classDiagram +Author +User +UserName +Kind put or delete +Path +Blob +Size +Mode +Note + +Mtime when the file was written } - note for Op "internal/journal — Less orders by (lamport, time, device, seq); Replay folds to LWW-per-path state; each device writes only its own journal" + note for Op "internal/journal — Less orders by (lamport, time, device, seq); Replay folds to LWW-per-path state; each device writes only its own journal. Mtime is display-only (bdrive log shows it, falling back to Time) and never feeds Less or Replay" class Backend { <> diff --git a/cmd/bdrive/cmds.go b/cmd/bdrive/cmds.go index 33aaf1a..7f8656d 100644 --- a/cmd/bdrive/cmds.go +++ b/cmd/bdrive/cmds.go @@ -266,16 +266,23 @@ func logCmd() *cobra.Command { if err != nil { return err } - entries, err := syncer.LogEntries(sess.Store, pathFilter, limit) + // Limit after the display sort, not before: -n 25 means the 25 + // newest by the time shown, not the 25 highest lamport. + entries, err := syncer.LogEntries(sess.Store, pathFilter, 0) if err != nil { return err } + syncer.SortForDisplay(entries) + if limit > 0 && len(entries) > limit { + entries = entries[:limit] + } + out := cmd.OutOrStdout() if len(entries) == 0 { - fmt.Println("no history yet") + fmt.Fprintln(out, "no history yet") return nil } for _, op := range entries { - when := op.Time.Local().Format("2006-01-02 15:04:05") + when := syncer.DisplayTime(op).Local().Format("2006-01-02 15:04:05") kind := op.Kind if kind == journal.KindPut { kind = "put " @@ -298,7 +305,7 @@ func logCmd() *cobra.Command { if op.Note != "" { line += " [" + op.Note + "]" } - fmt.Println(line) + fmt.Fprintln(out, line) } return nil }, diff --git a/cmd/bdrive/log_test.go b/cmd/bdrive/log_test.go new file mode 100644 index 0000000..2c33a12 --- /dev/null +++ b/cmd/bdrive/log_test.go @@ -0,0 +1,126 @@ +package main + +import ( + "bytes" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/runbear-io/beardrive/internal/config" +) + +// The reported bug was read off `bdrive log`'s own output, so assert on that +// output: every printed timestamp descends, the stamp is the file's edit time +// (files written minutes apart don't collapse onto one), and -n keeps the +// newest by that stamp rather than the highest lamport. +func TestLogPrintsNewestFirstByEditTime(t *testing.T) { + t.Setenv("BDRIVE_HOME", t.TempDir()) + folder := t.TempDir() + folder, _ = filepath.EvalSymlinks(folder) + if _, err := config.SaveProject(folder, config.Project{ + Volume: "wiki", + Remote: "https://hub.example.com/p/p-12345678", // unreachable: the cycle degrades offline + }); err != nil { + t.Fatal(err) + } + if _, _, err := config.ResolveMount(folder); err != nil { // enroll, as `bdrive init` would + t.Fatal(err) + } + + // Written in one scan, edited at three different times — and the newest + // edit is deliberately not the one the walk sees last. + now := time.Now() + files := map[string]time.Duration{ + "a-oldest.md": -30 * time.Minute, + "b-newest.md": -1 * time.Minute, + "c-middle.md": -10 * time.Minute, + } + for rel, age := range files { + abs := filepath.Join(folder, rel) + if err := os.WriteFile(abs, []byte("content of "+rel), 0o644); err != nil { + t.Fatal(err) + } + when := now.Add(age) + if err := os.Chtimes(abs, when, when); err != nil { + t.Fatal(err) + } + } + + sync := syncCmd() + sync.SetOut(&bytes.Buffer{}) + sync.SetArgs([]string{folder}) + if err := sync.Execute(); err != nil { + t.Fatalf("sync: %v", err) + } + + stamps, paths := runLog(t, folder) + if len(paths) != 3 { + t.Fatalf("got %d rows, want 3:\n%v", len(paths), paths) + } + if want := []string{"b-newest.md", "c-middle.md", "a-oldest.md"}; !equal(paths, want) { + t.Fatalf("row order = %v, want %v", paths, want) + } + for i := 1; i < len(stamps); i++ { + if stamps[i].After(stamps[i-1]) { + t.Fatalf("printed stamps are not newest-first: %v then %v", stamps[i-1], stamps[i]) + } + } + // Three edits minutes apart must print three distinct stamps; before this + // change one scan stamped them all with its own commit time. + if stamps[0].Equal(stamps[1]) || stamps[1].Equal(stamps[2]) { + t.Fatalf("stamps collapsed onto the sync time: %v", stamps) + } + + // -n truncates after the display sort. + _, top := runLog(t, folder, "-n", "2") + if want := []string{"b-newest.md", "c-middle.md"}; !equal(top, want) { + t.Fatalf("-n 2 = %v, want %v", top, want) + } + + // -p still filters to one path. + _, only := runLog(t, folder, "-p", "c-middle.md") + if want := []string{"c-middle.md"}; !equal(only, want) { + t.Fatalf("-p = %v, want %v", only, want) + } +} + +// runLog runs `bdrive log` and parses the printed timestamp + path columns. +func runLog(t *testing.T, folder string, extra ...string) ([]time.Time, []string) { + t.Helper() + c := logCmd() + var out bytes.Buffer + c.SetOut(&out) + c.SetArgs(append([]string{folder}, extra...)) + if err := c.Execute(); err != nil { + t.Fatalf("log: %v", err) + } + var stamps []time.Time + var paths []string + for _, line := range strings.Split(strings.TrimSpace(out.String()), "\n") { + if line == "" { + continue + } + ts, err := time.ParseInLocation("2006-01-02 15:04:05", line[:19], time.Local) + if err != nil { + t.Fatalf("unparsable log row %q: %v", line, err) + } + fields := strings.Fields(line[19:]) + stamps = append(stamps, ts) + paths = append(paths, fields[1]) + } + return stamps, paths +} + +func equal(a, b []string) bool { + if len(a) != len(b) { + return false + } + for i := range a { + if a[i] != b[i] { + return false + } + } + return true +} diff --git a/internal/journal/journal.go b/internal/journal/journal.go index 4f11ddc..912bfc8 100644 --- a/internal/journal/journal.go +++ b/internal/journal/journal.go @@ -39,6 +39,10 @@ type Op struct { Size int64 `json:"size,omitempty"` Mode uint32 `json:"mode,omitempty"` // permission bits Note string `json:"note,omitempty"` // e.g. "conflict copy of " + // Mtime is when the file was last written, as opposed to Time, which is + // when the op was committed. Display only — never an input to Less or + // Replay, since it comes from the filesystem and can be anything. + Mtime time.Time `json:"mtime,omitzero"` // put only } // Less defines the total order used to replay ops from many devices. diff --git a/internal/journal/journal_test.go b/internal/journal/journal_test.go index 788b4d4..800b420 100644 --- a/internal/journal/journal_test.go +++ b/internal/journal/journal_test.go @@ -3,6 +3,7 @@ package journal import ( "os" "path/filepath" + "strings" "testing" "time" ) @@ -93,3 +94,37 @@ func TestParseSkipsBlankLines(t *testing.T) { t.Fatalf("got %v %v", got, err) } } + +// TestMtimeIsAdditive pins the wire shape: an op carrying Mtime round-trips, +// and an op without one emits no "mtime" key at all — so a journal written by +// this code still parses in the old shape. (omitempty would not do this: it +// does not omit a zero struct.) +func TestMtimeIsAdditive(t *testing.T) { + mt := time.Unix(1700000000, 0).UTC() + with := op(1, "a", 1, KindPut, "x.txt", "blob1") + with.Mtime = mt + without := op(2, "a", 2, KindDelete, "x.txt", "") + + data, err := Marshal([]Op{with, without}) + if err != nil { + t.Fatal(err) + } + lines := strings.Split(strings.TrimSpace(string(data)), "\n") + if !strings.Contains(lines[0], `"mtime"`) { + t.Fatalf("put op lost its mtime: %s", lines[0]) + } + if strings.Contains(lines[1], "mtime") { + t.Fatalf("op without mtime should emit no mtime key: %s", lines[1]) + } + + got, err := Parse(data) + if err != nil { + t.Fatal(err) + } + if !got[0].Mtime.Equal(mt) { + t.Fatalf("Mtime = %v, want %v", got[0].Mtime, mt) + } + if !got[1].Mtime.IsZero() { + t.Fatalf("Mtime should be zero, got %v", got[1].Mtime) + } +} diff --git a/internal/syncer/syncer.go b/internal/syncer/syncer.go index 26060d7..e3139ee 100644 --- a/internal/syncer/syncer.go +++ b/internal/syncer/syncer.go @@ -360,6 +360,7 @@ func (s *Session) scan(cache map[string]store.CachedFile, st *store.SyncState, s } op := nextOp(journal.KindPut, rel) op.Blob, op.Size, op.Mode = sum, n, mode + op.Mtime = info.ModTime().UTC() ops = append(ops, op) cache[rel] = store.CachedFile{Blob: sum, Size: n, Mode: mode, MTimeNS: mt} return nil @@ -822,6 +823,31 @@ func pruneEmptyDirs(root, dir string) { } } +// DisplayTime is the timestamp to show a human for an op: when the file was +// written if we know it, otherwise when the op was committed. Ops written +// before Op.Mtime existed, and deletes (no file left to stat), fall back. +func DisplayTime(op journal.Op) time.Time { + if !op.Mtime.IsZero() { + return op.Mtime + } + return op.Time +} + +// SortForDisplay orders ops newest-first by DisplayTime — the timestamp the +// user actually sees, so the list reads as a timeline. Ties fall back to +// reversed journal.Less to stay deterministic. This is deliberately NOT the +// replay order: LogEntries keeps returning causal order because +// bdrive restore walks it to find a file's previous version. +func SortForDisplay(ops []journal.Op) { + sort.SliceStable(ops, func(i, j int) bool { + ti, tj := DisplayTime(ops[i]), DisplayTime(ops[j]) + if !ti.Equal(tj) { + return ti.After(tj) + } + return journal.Less(ops[j], ops[i]) + }) +} + // LogEntries returns the volume history, newest first. func LogEntries(st *store.Store, pathFilter string, limit int) ([]journal.Op, error) { all, err := st.AllOps() diff --git a/internal/syncer/syncer_test.go b/internal/syncer/syncer_test.go index 84ba5ba..89ef847 100644 --- a/internal/syncer/syncer_test.go +++ b/internal/syncer/syncer_test.go @@ -15,6 +15,7 @@ import ( "time" "github.com/runbear-io/beardrive/internal/config" + "github.com/runbear-io/beardrive/internal/journal" "github.com/runbear-io/beardrive/internal/remote" "github.com/runbear-io/beardrive/internal/store" ) @@ -576,3 +577,136 @@ func snapshotDir(t *testing.T, folder string) map[string]string { } return out } + +func touch(t *testing.T, folder, rel string, when time.Time) { + t.Helper() + abs := filepath.Join(folder, filepath.FromSlash(rel)) + if err := os.Chtimes(abs, when, when); err != nil { + t.Fatal(err) + } +} + +// TestLogDisplayOrder builds exactly the skew that made `bdrive log` +// unreadable: device B commits after pulling A, so B's op carries the HIGHER +// lamport, while B's file was written hours EARLIER on the wall clock. Causal +// order and clock order disagree — the display sort must follow the clock. +func TestLogDisplayOrder(t *testing.T) { + be := sharedRemote(t) + a, b := newDevice(t, "deva", be), newDevice(t, "devb", be) + + write(t, b.Folder, "early.md", "written two hours ago") + touch(t, b.Folder, "early.md", time.Now().Add(-2*time.Hour)) + write(t, a.Folder, "late.md", "written just now") + + cycle(t, a) // lamport 1 + cycle(t, b) // pulls A (lamport 1), commits its own op at lamport 2 + cycle(t, a) // pull B, so A's store holds both journals + + entries, err := LogEntries(a.Store, "", 0) + if err != nil { + t.Fatal(err) + } + if len(entries) != 2 { + t.Fatalf("got %d entries, want 2: %+v", len(entries), entries) + } + // Precondition: the two orders really do disagree. Without this, the + // assertion below would pass even if SortForDisplay did nothing. + if entries[0].Path != "early.md" { + t.Fatalf("causal order should lead with the higher-lamport op early.md, got %q", entries[0].Path) + } + + SortForDisplay(entries) + if entries[0].Path != "late.md" { + t.Fatalf("display order should lead with the newest file late.md, got %q", entries[0].Path) + } + assertNonIncreasing(t, entries) +} + +// TestLogDisplayTimeIsEditTime covers the other half of the report: 22 ops of +// one agent run all printed the same stamp because Time is the commit time. +// Two files written a minute apart and committed in ONE cycle must carry two +// different display times. +func TestLogDisplayTimeIsEditTime(t *testing.T) { + a := newDevice(t, "deva", sharedRemote(t)) + write(t, a.Folder, "first.md", "one") + write(t, a.Folder, "second.md", "two") + touch(t, a.Folder, "first.md", time.Now().Add(-2*time.Minute)) + touch(t, a.Folder, "second.md", time.Now().Add(-1*time.Minute)) + cycle(t, a) + + entries, err := LogEntries(a.Store, "", 0) + if err != nil { + t.Fatal(err) + } + if len(entries) != 2 { + t.Fatalf("got %d entries, want 2", len(entries)) + } + byPath := map[string]journal.Op{} + for _, op := range entries { + if op.Mtime.IsZero() { + t.Fatalf("put op %s has no Mtime", op.Path) + } + // Commit times are microseconds apart — indistinguishable at the + // second resolution `bdrive log` prints, which is why one scan used + // to collapse a whole agent run onto a single stamp. + if d := op.Time.Sub(entries[0].Time); d > time.Second || d < -time.Second { + t.Fatalf("expected both ops committed in one batch, Time differs by %v", d) + } + byPath[op.Path] = op + } + gap := DisplayTime(byPath["second.md"]).Sub(DisplayTime(byPath["first.md"])) + if gap < 30*time.Second { + t.Fatalf("display times only %v apart; one scan collapsed them again", gap) + } + + SortForDisplay(entries) + if entries[0].Path != "second.md" { + t.Fatalf("newest edit should lead, got %q", entries[0].Path) + } +} + +// TestSortForDisplayFallsBackToTime covers journals written before Op.Mtime +// existed, and deletes, which never carry one: they sort and print by Time and +// must not sink to the bottom as zero-time rows. +func TestSortForDisplayFallsBackToTime(t *testing.T) { + base := time.Date(2026, 7, 29, 6, 0, 0, 0, time.UTC) + mk := func(path string, lamport int64, kind string, commit, mtime time.Time) journal.Op { + return journal.Op{ + Seq: lamport, Lamport: lamport, Time: commit, Mtime: mtime, + Device: "deva", Kind: kind, Path: path, + } + } + ops := []journal.Op{ + mk("legacy-old.md", 1, journal.KindPut, base, time.Time{}), // no mtime + mk("gone.md", 2, journal.KindDelete, base.Add(3*time.Minute), time.Time{}), + mk("legacy-new.md", 3, journal.KindPut, base.Add(4*time.Minute), time.Time{}), + mk("fresh.md", 4, journal.KindPut, base.Add(9*time.Minute), base.Add(2*time.Minute)), + } + SortForDisplay(ops) + + want := []string{"legacy-new.md", "gone.md", "fresh.md", "legacy-old.md"} + for i, w := range want { + if ops[i].Path != w { + t.Fatalf("order[%d] = %q, want %q (full: %v)", i, ops[i].Path, w, paths(ops)) + } + } + assertNonIncreasing(t, ops) +} + +func paths(ops []journal.Op) []string { + out := make([]string, len(ops)) + for i, op := range ops { + out[i] = op.Path + } + return out +} + +func assertNonIncreasing(t *testing.T, ops []journal.Op) { + t.Helper() + for i := 1; i < len(ops); i++ { + if DisplayTime(ops[i]).After(DisplayTime(ops[i-1])) { + t.Fatalf("display order not newest-first at %d: %v then %v", + i, DisplayTime(ops[i-1]), DisplayTime(ops[i])) + } + } +} diff --git a/web/docs/src/content/docs/reference/cli.md b/web/docs/src/content/docs/reference/cli.md index a3f2d33..9618cfe 100644 --- a/web/docs/src/content/docs/reference/cli.md +++ b/web/docs/src/content/docs/reference/cli.md @@ -24,7 +24,7 @@ One binary, `bdrive` — the CLI, the sync daemon, and the web server. | `bdrive hooks [install\|uninstall]` | Register turn-boundary sync hooks in each detected agent platform's user config — once per machine, covering every folder. Run automatically by `bdrive init`; idempotent; `--agent` overrides detection. `uninstall` removes only BearDrive's own hook entries | | `bdrive read-log [folder]` | Hook plumbing: queue agent file reads for the hub's read heatmap. Registered by `bdrive hooks install` | | `bdrive status [folder]` | Projects, daemon state, pending changes | -| `bdrive log [folder] [-p path] [-n N]` | Change history: account, device, time, file | +| `bdrive log [folder] [-p path] [-n N]` | Change history: account, device, time, file — newest first by the time shown, which is when the file was written (ops recorded before this was tracked, and deletes, show their sync time instead) | | `bdrive restore [version]` | Put an earlier version of a file back, as a new change. No version restores the previous one; `--list` shows the versions with their short hashes | | `bdrive export [folder]` | Export the whole project — all devices' history and content — to a portable `.tar.gz` (`-o` names the file) | | `bdrive import ` | Import an export archive as a new project on the hub you're logged into (`--name` overrides the archive's name) |