fix(cli): bdrive log sorts by when a change arrived (BEA-112) (#174)

`mv a.md b.md` produced two rows minutes apart: the delete carried the
rename's time, the put carried the original file's mtime, so a file that
appeared seconds ago sorted below the fold of "what changed since
yesterday" — the question `bdrive log` exists to answer.

SortForDisplay now orders by CommitTime (when the change was journaled),
tie-breaking on DisplayTime so one scan still reads by the files' own
edit times. The write time is still shown, appended as `written <time>`
when it lags the commit by more than a minute — a rename, or an old
document added today — rather than silently replacing the column.

DisplayTime and both of its security clamps are untouched. CommitTime
carries the same clamp: an op stamped after this machine's clock cannot
date itself, so it sorts last rather than first.

One deviation from the plan: it assumed a scan shares one commit time,
but nextOp stamped time.Now() per op, so the tie-break never engaged and
one scan sorted in walk order. A scan is now one commit instant — order
inside the batch is already carried by Lamport and Seq, which
journal.Less reads first, so replay is unaffected.

journal.Less, Replay, LogEntries' causal order and the op format are
unchanged. The hub's History is a separate path and still orders a
rename by write time.
This commit is contained in:
Snow Lee (Sungwon)
2026-08-18 22:10:02 -07:00
committed by GitHub
parent 432eba1b49
commit 333d1fb8e5
7 changed files with 270 additions and 49 deletions
+1 -1
View File
@@ -260,7 +260,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, two separate change counts — `pending` (journalled, not yet pushed) and `local` (on disk, not yet scanned — what a stopped daemon leaves invisible) — and any synced files that looked like they held credentials when they last changed. Pure local read: no ops, no journal writes, no network |
| `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 log [folder] [-p path] [-n N]` | Change history: account, device, time, file — newest first by the time shown, which is when the change was journaled; a file written more than a minute before it arrived (a rename, or an old document added today) also shows `written <time>` |
| `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. To un-create a file a run *created*, use **undo — remove file** on that row in the hub's History view — or **undo this run** in the run card's header to put back every file that run touched at once |
| `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 (always a NEW project; `--name` overrides the archive's); history and authorship carry over. Refuses an archive whose journals reference content it doesn't hold (`--allow-incomplete` overrides). Move projects between hubs — cloud → self-hosted or back — with `export` + `login` + `import` |
+1 -1
View File
@@ -31,7 +31,7 @@ classDiagram
-fetchChunked(ctx, op, basis) error
-chunkSpans(blob) []span
}
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 "syncer also exposes LogEntries (causal order, what bdrive restore walks) plus CommitTime / DisplayTime / SortForDisplay — the order bdrive log prints: newest-first by when a change was journaled (CommitTime), tie-broken by the file's own write time (DisplayTime) so one scan reads by edit time"
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 → adopt on join → re-assert withdrawn ops → preserve conflicts → refresh rules → prune → materialize → push blobs then own journal"
note for Session "pull returns TWO lists: newly seen ops, and `gone` — ops a peer deleted from a journal this device had already applied. A peer cannot un-say what we already hold: stillHold re-signs each still-held put into OUR journal (reassertNote). Pull resumes at a byte offset by prefix-matching the local journal copy, so a peer's growing journal is read once"
+17 -1
View File
@@ -297,6 +297,10 @@ func statusCmd() *cobra.Command {
}
}
// writeGap is how far a file's write time must lag the moment it was journaled
// before `bdrive log` prints both.
const writeGap = time.Minute
func logCmd() *cobra.Command {
var limit int
var pathFilter string
@@ -329,7 +333,8 @@ func logCmd() *cobra.Command {
return nil
}
for _, op := range entries {
when := syncer.DisplayTime(op).Local().Format("2006-01-02 15:04:05")
commit := syncer.CommitTime(op)
when := commit.Local().Format("2006-01-02 15:04:05")
kind := op.Kind
if kind == journal.KindPut {
kind = "put "
@@ -350,6 +355,17 @@ func logCmd() *cobra.Command {
if op.Kind == journal.KindPut {
line += fmt.Sprintf(" (%s)", humanBytes(op.Size))
}
// The first column is when the change was journaled, so the
// rows read monotonically. The file's own write time still
// matters — but the daemon scans every 3s and a hook sync is
// prompt, so a sub-minute gap is just scan latency and would be
// noise on every row. A larger gap means the file genuinely
// predates its arrival here — a rename, or an old document
// added today — and that is the case the reader has to see.
// Deletes have no file left to stat, so they never carry it.
if written := syncer.DisplayTime(op); commit.Sub(written) >= writeGap {
line += fmt.Sprintf(" (written %s)", written.Local().Format("2006-01-02 15:04:05"))
}
if note := safeField(op.Note, 200); note != "" {
line += " [" + note + "]"
}
+187 -29
View File
@@ -12,9 +12,13 @@ import (
)
// 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.
// output: every printed timestamp descends, the file's edit time still reaches
// the reader (files written minutes apart don't collapse onto one), and -n
// keeps the newest by that stamp rather than the highest lamport.
//
// The first column is now when the change was journaled, so the edit time it
// used to carry is asserted where it is now printed — the appended
// `written ...` field. That is BEA-40's guarantee, moved, not dropped.
func TestLogPrintsNewestFirstByEditTime(t *testing.T) {
t.Setenv("BDRIVE_HOME", t.TempDir())
folder := t.TempDir()
@@ -55,39 +59,177 @@ func TestLogPrintsNewestFirstByEditTime(t *testing.T) {
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)
rows := runLog(t, folder)
if len(rows) != 3 {
t.Fatalf("got %d rows, want 3:\n%v", len(rows), paths(rows))
}
if want := []string{"b-newest.md", "c-middle.md", "a-oldest.md"}; !equal(paths, want) {
t.Fatalf("row order = %v, want %v", paths, want)
if want := []string{"b-newest.md", "c-middle.md", "a-oldest.md"}; !equal(paths(rows), want) {
t.Fatalf("row order = %v, want %v", paths(rows), 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])
for i := 1; i < len(rows); i++ {
if rows[i].stamp.After(rows[i-1].stamp) {
t.Fatalf("printed stamps are not newest-first: %v then %v", rows[i-1].stamp, rows[i].stamp)
}
}
// 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)
// Three edits minutes apart must still reach the reader as three distinct
// write times; before BEA-40 one scan stamped them all with its own time.
for i, r := range rows {
if r.written.IsZero() {
t.Fatalf("row %d (%s) dropped the file's write time", i, r.path)
}
}
if rows[0].written.Equal(rows[1].written) || rows[1].written.Equal(rows[2].written) {
t.Fatalf("write times collapsed onto the sync time: %v %v %v",
rows[0].written, rows[1].written, rows[2].written)
}
// -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)
top := runLog(t, folder, "-n", "2")
if want := []string{"b-newest.md", "c-middle.md"}; !equal(paths(top), want) {
t.Fatalf("-n 2 = %v, want %v", paths(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)
only := runLog(t, folder, "-p", "c-middle.md")
if want := []string{"c-middle.md"}; !equal(paths(only), want) {
t.Fatalf("-p = %v, want %v", paths(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) {
// A rename is one change, and `mv` preserves mtime — so before this, the put
// half was stamped with the original file's write time and sorted away from
// its own delete, which is how a file that appeared seconds ago falls below
// the fold of "what changed since yesterday".
func TestLogKeepsARenameTogether(t *testing.T) {
folder := logFixture(t)
old := filepath.Join(folder, "architecture.md")
if err := os.WriteFile(old, []byte("# architecture"), 0o644); err != nil {
t.Fatal(err)
}
// Written well before the rename: the gap is the bug.
long := time.Now().Add(-90 * time.Minute)
if err := os.Chtimes(old, long, long); err != nil {
t.Fatal(err)
}
// Filler, so "adjacent at the top" is a real claim and not the only rows.
for _, rel := range []string{"notes.md", "todo.md"} {
if err := os.WriteFile(filepath.Join(folder, rel), []byte(rel), 0o644); err != nil {
t.Fatal(err)
}
}
runSync(t, folder)
if err := os.Rename(old, filepath.Join(folder, "arch-v2.md")); err != nil {
t.Fatal(err)
}
runSync(t, folder)
rows := runLog(t, folder)
if len(rows) < 2 {
t.Fatalf("got %d rows, want the rename plus fillers: %v", len(rows), paths(rows))
}
// The two halves are one change and sit together at the top. The delete
// leads: it has no file left to stat, so it sorts on the commit time while
// the put still carries its 90-minute-old write time as the tie-break.
got := []string{rows[0].kind + " " + rows[0].path, rows[1].kind + " " + rows[1].path}
want := []string{"delete architecture.md", "put arch-v2.md"}
if !equal(got, want) {
t.Fatalf("top two rows = %v, want the rename's two halves %v\nall: %v", got, want, paths(rows))
}
if !rows[0].stamp.Equal(rows[1].stamp) {
t.Fatalf("one rename printed two stamps: %v and %v", rows[0].stamp, rows[1].stamp)
}
// The write time is what makes the 90-minute gap legible instead of silent.
if rows[1].written.IsZero() {
t.Fatal("the put half dropped the file's write time")
}
if gap := rows[1].stamp.Sub(rows[1].written); gap < time.Hour {
t.Fatalf("put half's write time = %v, stamp = %v: the original mtime was lost",
rows[1].written, rows[1].stamp)
}
// A delete has no file left to stat, so it never carries the field.
if !rows[0].written.IsZero() {
t.Fatalf("delete row carried a write time: %v", rows[0].written)
}
}
// An old document dropped into the project today is a change today. It used to
// sort by its own mtime, i.e. below everything journaled since it was written.
func TestLogSortsAnOldFileByWhenItArrived(t *testing.T) {
folder := logFixture(t)
recent := filepath.Join(folder, "recent.md")
if err := os.WriteFile(recent, []byte("edited a minute ago"), 0o644); err != nil {
t.Fatal(err)
}
fresh := time.Now().Add(-2 * time.Minute)
if err := os.Chtimes(recent, fresh, fresh); err != nil {
t.Fatal(err)
}
runSync(t, folder)
// Journaled second, written days before the file above it.
ancient := filepath.Join(folder, "ancient.md")
if err := os.WriteFile(ancient, []byte("from the archive"), 0o644); err != nil {
t.Fatal(err)
}
old := time.Now().Add(-72 * time.Hour)
if err := os.Chtimes(ancient, old, old); err != nil {
t.Fatal(err)
}
runSync(t, folder)
rows := runLog(t, folder)
if want := []string{"ancient.md", "recent.md"}; !equal(paths(rows), want) {
t.Fatalf("row order = %v, want %v — the newly arrived file sorts first", paths(rows), want)
}
if rows[0].written.IsZero() || rows[0].stamp.Sub(rows[0].written) < 24*time.Hour {
t.Fatalf("ancient.md lost its write time: stamp %v, written %v", rows[0].stamp, rows[0].written)
}
}
// logFixture is an enrolled folder pointed at an unreachable hub, so the cycle
// degrades offline and the journal is all local.
func logFixture(t *testing.T) string {
t.Helper()
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",
}); err != nil {
t.Fatal(err)
}
if _, _, err := config.EnrollMount(folder); err != nil {
t.Fatal(err)
}
return folder
}
func runSync(t *testing.T, folder string) {
t.Helper()
c := syncCmd()
c.SetOut(&bytes.Buffer{})
c.SetArgs([]string{folder})
if err := c.Execute(); err != nil {
t.Fatalf("sync: %v", err)
}
}
// logRow is one parsed `bdrive log` line: the leading stamp (when the change
// was journaled), the kind and path columns, and the appended write time when
// the row carries one.
type logRow struct {
stamp time.Time
written time.Time
kind string
path string
}
// runLog runs `bdrive log` and parses its rows.
func runLog(t *testing.T, folder string, extra ...string) []logRow {
t.Helper()
c := logCmd()
var out bytes.Buffer
@@ -96,21 +238,37 @@ func runLog(t *testing.T, folder string, extra ...string) ([]time.Time, []string
if err := c.Execute(); err != nil {
t.Fatalf("log: %v", err)
}
var stamps []time.Time
var paths []string
const stampFmt = "2006-01-02 15:04:05"
var rows []logRow
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)
ts, err := time.ParseInLocation(stampFmt, 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])
row := logRow{stamp: ts, kind: fields[0], path: fields[1]}
if _, rest, ok := strings.Cut(line, "(written "); ok {
stamp, _, _ := strings.Cut(rest, ")")
w, err := time.ParseInLocation(stampFmt, stamp, time.Local)
if err != nil {
t.Fatalf("unparsable write time in %q: %v", line, err)
}
row.written = w
}
rows = append(rows, row)
}
return stamps, paths
return rows
}
func paths(rows []logRow) []string {
out := make([]string, len(rows))
for i, r := range rows {
out[i] = r.path
}
return out
}
func equal(a, b []string) bool {
+37 -7
View File
@@ -649,11 +649,18 @@ func (s *Session) scan(cache map[string]store.CachedFile, st *store.SyncState, s
if note == "" {
note = s.Store.LoadNote()
}
// One scan is one commit: every op it produces carries the same Time. Op
// order inside the batch is already carried by Lamport and Seq, which
// journal.Less consults first and second — so replay is unaffected — while
// a shared Time is what lets `bdrive log` recognise a batch and order it by
// the files' own write times (SortForDisplay). Stamping each op separately
// made a rename's two halves two different instants, which is the bug.
committed := time.Now().UTC()
nextOp := func(kind, rel string) journal.Op {
st.Lamport = tickLamport(st.Lamport)
seqBase++
return journal.Op{
Seq: seqBase, Lamport: st.Lamport, Time: time.Now().UTC(),
Seq: seqBase, Lamport: st.Lamport, Time: committed,
Device: s.Device.ID, DeviceName: s.Device.Name, Author: s.Device.Author,
User: s.Account.Email, UserName: s.Account.Name,
Kind: kind, Path: rel, Note: note, Session: s.SessionID,
@@ -1700,17 +1707,40 @@ func DisplayTime(op journal.Op) time.Time {
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.
// CommitTime is when a change entered the project, which is the question
// `bdrive log` answers. It is not DisplayTime: `mv` preserves mtime, so the put
// half of a rename carries the original file's write time and sorts away from
// the delete half of the same rename — a file that appeared seconds ago lands
// below the fold.
//
// Same clamp as DisplayTime, for the same reason: Op.Time is a peer's JSON, and
// the one clock a peer does not own is this machine's. An op we cannot date
// sorts last rather than first, which is the direction that cannot be aimed.
func CommitTime(op journal.Op) time.Time {
if op.Time.After(time.Now()) {
return time.Time{}
}
return op.Time
}
// SortForDisplay orders ops newest-first by CommitTime — when the change
// entered the project — so the two halves of a rename sit together and an old
// file added today sorts by when it arrived. DisplayTime breaks ties and is
// load-bearing: everything from one scan shares a commit second, and the files'
// own write times are the only thing that orders it inside that second. Ties
// beyond that 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])
ti, tj := CommitTime(ops[i]), CommitTime(ops[j])
if !ti.Equal(tj) {
return ti.After(tj)
}
di, dj := DisplayTime(ops[i]), DisplayTime(ops[j])
if !di.Equal(dj) {
return di.After(dj)
}
return journal.Less(ops[j], ops[i])
})
}
+26 -9
View File
@@ -682,10 +682,16 @@ func touch(t *testing.T, folder, rel string, when time.Time) {
}
}
// 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.
// TestLogDisplayOrder builds 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.
//
// The display sort follows the commit clock: early.md was written two hours
// ago but only ARRIVED in the project on B's cycle, and "what changed" means
// what arrived. Its own write time still reaches the reader — `bdrive log`
// prints it alongside — but it is not what orders the list. Before BEA-112
// the write time was the sort key, which is how the two halves of one rename
// landed a minute apart.
func TestLogDisplayOrder(t *testing.T) {
be := sharedRemote(t)
a, b := newDevice(t, "deva", be), newDevice(t, "devb", be)
@@ -712,8 +718,12 @@ func TestLogDisplayOrder(t *testing.T) {
}
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)
if entries[0].Path != "early.md" {
t.Fatalf("display order should lead with the most recently journaled file early.md, got %q", entries[0].Path)
}
// Its write time is two hours old and still available to print.
if gap := entries[0].Time.Sub(DisplayTime(entries[0])); gap < time.Hour {
t.Fatalf("early.md's write time was lost: commit %v, display %v", entries[0].Time, DisplayTime(entries[0]))
}
assertNonIncreasing(t, entries)
}
@@ -780,7 +790,10 @@ func TestSortForDisplayFallsBackToTime(t *testing.T) {
}
SortForDisplay(ops)
want := []string{"legacy-new.md", "gone.md", "fresh.md", "legacy-old.md"}
// Ordered by commit time. legacy ops and deletes carry no mtime, and the
// point of the fallback is that they sort on their commit time like
// everything else rather than sinking to the bottom as zero-time rows.
want := []string{"fresh.md", "legacy-new.md", "gone.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))
@@ -797,12 +810,16 @@ func paths(ops []journal.Op) []string {
return out
}
// assertNonIncreasing pins BEA-40's guarantee on the key the display sort now
// uses: `bdrive log` reads strictly newest-first by commit time, the column it
// prints. DisplayTime is deliberately not monotone down the list — an old file
// journaled today belongs at the top wearing its old write time.
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])) {
if CommitTime(ops[i]).After(CommitTime(ops[i-1])) {
t.Fatalf("display order not newest-first at %d: %v then %v",
i, DisplayTime(ops[i-1]), DisplayTime(ops[i]))
i, CommitTime(ops[i-1]), CommitTime(ops[i]))
}
}
}
+1 -1
View File
@@ -26,7 +26,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, and any synced files that looked like they held credentials when they last changed |
| `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 log [folder] [-p path] [-n N]` | Change history: account, device, time, file — newest first by the time shown, which is when the change was journaled; a file written more than a minute before it arrived (a rename, or an old document added today) also shows `written <time>` |
| `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) |