fix(log): bdrive log reads as a timeline — newest first by edit time (#BEA-40) (#90)

`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) <noreply@anthropic.com>

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 <file> [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 <archive>` | 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` |

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 {
         <<interface>>

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
 		},

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
+}

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 <path>"
+	// 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.

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)
+	}
+}

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()

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]))
+		}
+	}
+}

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 <file> [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 <archive>` | Import an export archive as a new project on the hub you're logged into (`--name` overrides the archive's name) |