wip: add telemetry instrumentation to FileTime and tighten tolerance

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Author: anandgupta42

packages/opencode/src/altimate/telemetry/index.ts

@@ -481,6 +481,34 @@ export namespace Telemetry {
         masked_args?: string
         duration_ms: number
       }
+    // altimate_change start — FileTime observability: drift + assertion outcome tracking
+    // Tracks the gap between Node.js wall-clock and filesystem mtime at read time.
+    // Use to monitor whether the mtime clock-source change (PR #611) is preventing
+    // false stale-file errors, and detect environments with significant drift.
+    // KQL: customEvents | where name == "filetime_drift" | extend drift = todouble(customMeasurements.drift_ms)
+    | {
+        type: "filetime_drift"
+        timestamp: number
+        session_id: string
+        /** Absolute difference in ms between Date.now() and filesystem mtime */
+        drift_ms: number
+        /** True if filesystem mtime is ahead of wall-clock (the problematic direction) */
+        mtime_ahead: boolean
+      }
+    // Tracks FileTime.assert() outcomes: "stale" when a file fails the check.
+    // High volume of "stale" with low delta_ms suggests tolerance is too tight.
+    // KQL: customEvents | where name == "filetime_assert" | extend delta = todouble(customMeasurements.delta_ms)
+    | {
+        type: "filetime_assert"
+        timestamp: number
+        session_id: string
+        outcome: "stale"
+        /** mtime - readTime in ms (how far ahead the file's mtime is) */
+        delta_ms: number
+        /** Current tolerance threshold in ms */
+        tolerance_ms: number
+      }
+    // altimate_change end
     // altimate_change start — sql quality telemetry for issue prevention metrics
     | {
         type: "sql_quality"

packages/opencode/src/file/time.ts

@@ -2,9 +2,48 @@ import { Instance } from "../project/instance"
 import { Log } from "../util/log"
 import { Flag } from "../flag/flag"
 import { Filesystem } from "../util/filesystem"
+// altimate_change start — telemetry for FileTime drift measurement
+import { Telemetry } from "../altimate/telemetry"
+// altimate_change end
 
 export namespace FileTime {
   const log = Log.create({ service: "file.time" })
+
+  // altimate_change start — FileTime clock source change documentation
+  //
+  // CHANGE: read() now records the file's filesystem mtime instead of Date.now().
+  //
+  // WHY: The original code used `new Date()` (wall-clock) as the "last read" timestamp,
+  // then assert() compared it against `Filesystem.stat(file).mtime`. On WSL (NTFS-over-9P),
+  // networked drives, and some macOS APFS mounts, the filesystem clock drifts 400ms–1.2s
+  // behind Node.js's clock. This caused mtime > readTime even for the file's own write,
+  // triggering false "modified since last read" errors. One user hit 782 consecutive retries.
+  //
+  // FIX: Both timestamps now come from the same clock (filesystem mtime), eliminating
+  // cross-clock skew. The tolerance is kept at 50ms (upstream default) since same-clock
+  // comparisons don't need a larger window.
+  //
+  // TRADE-OFF: On coarse-resolution filesystems (HFS+ = 1s, NFS with stale cache,
+  // Docker overlayfs after copy-up), two writes within the same resolution window
+  // produce identical mtimes — so we'd miss a real external modification. This is a
+  // false-negative risk (missed edit) vs the false-positive risk (retry loop) we're
+  // fixing. Acceptable because: (a) the file gets re-read on the next attempt anyway,
+  // (b) HFS+ is rare (macOS defaulted to APFS since 2017), and (c) the wall-clock
+  // approach was actively causing 782-retry production loops on WSL.
+  //
+  // MONITORING: filetime_drift telemetry event tracks the gap between wall-clock and mtime
+  // at read time. If drift_ms is consistently 0, this change has no effect (good). If
+  // drift_ms shows large values, this change is preventing false positives (also good).
+  // If file_stale errors increase post-deploy, the tolerance may need adjustment.
+  //
+  // UPSTREAM: sst/opencode issues #19040, #14183, #20354 track the same problem.
+  // Upstream is pursuing processor-level recovery (PR #19099) rather than fixing the clock
+  // source. Both approaches are complementary.
+  //
+  // ROLLBACK: Set OPENCODE_DISABLE_FILETIME_CHECK=true to bypass all checks, or revert
+  // this change to restore `new Date()` behavior with a wider tolerance.
+  // altimate_change end
+
   // Per-session read times plus per-file write locks.
   // All tools that overwrite existing files should run their
   // assert/read/write/update sequence inside withLock(filepath, ...)
@@ -26,12 +65,32 @@ export namespace FileTime {
     log.info("read", { sessionID, file })
     const { read } = state()
     read[sessionID] = read[sessionID] || {}
-    // Use the file's actual mtime instead of wall-clock time to avoid
-    // clock drift between Node.js and the filesystem (especially on WSL,
-    // networked drives, and macOS APFS). This eliminates the race condition
-    // where mtime > new Date() due to filesystem clock skew.
+    // altimate_change start — use filesystem mtime instead of wall-clock (see doc block above)
+    const wallClock = new Date()
     const mtime = Filesystem.stat(file)?.mtime
-    read[sessionID][file] = mtime ?? new Date()
+    read[sessionID][file] = mtime ?? wallClock
+
+    // Track drift between wall-clock and filesystem mtime for monitoring.
+    // This lets us measure the real-world impact of the clock source change
+    // and detect environments where drift is significant.
+    if (mtime) {
+      const driftMs = Math.abs(wallClock.getTime() - mtime.getTime())
+      if (driftMs > 10) {
+        // Only emit when drift is non-trivial (>10ms) to avoid noise
+        try {
+          Telemetry.track({
+            type: "filetime_drift",
+            timestamp: Date.now(),
+            session_id: sessionID,
+            drift_ms: driftMs,
+            mtime_ahead: mtime.getTime() > wallClock.getTime(),
+          })
+        } catch {
+          // Telemetry must never break file operations
+        }
+      }
+    }
+    // altimate_change end
   }
 
   export function get(sessionID: string, file: string) {
@@ -66,14 +125,27 @@ export namespace FileTime {
     const time = get(sessionID, filepath)
     if (!time) throw new Error(`You must read file ${filepath} before overwriting it. Use the Read tool first`)
     const mtime = Filesystem.stat(filepath)?.mtime
-    // Allow a 2s tolerance for filesystem clock drift.
-    // WSL (NTFS-over-9P) and networked drives routinely show 400ms–1.2s gaps
-    // between Node.js Date.now() and filesystem mtime. The previous 50ms
-    // tolerance caused massive retry loops (782 retries in one session).
-    if (mtime && mtime.getTime() > time.getTime() + 2000) {
+    // altimate_change start — keep upstream's 50ms tolerance (sufficient now that both
+    // timestamps come from the same filesystem clock). Track assertion outcomes for monitoring.
+    const toleranceMs = 50
+    const deltaMs = mtime ? mtime.getTime() - time.getTime() : 0
+    if (mtime && deltaMs > toleranceMs) {
+      try {
+        Telemetry.track({
+          type: "filetime_assert",
+          timestamp: Date.now(),
+          session_id: sessionID,
+          outcome: "stale",
+          delta_ms: deltaMs,
+          tolerance_ms: toleranceMs,
+        })
+      } catch {
+        // Telemetry must never mask the stale-file error
+      }
       throw new Error(
-        `File ${filepath} has been modified since it was last read.\nLast modification: ${mtime.toISOString()}\nLast read: ${time.toISOString()}\n\nPlease read the file again before modifying it.`,
+        `File ${filepath} has been modified since it was last read.\nLast modification: ${mtime.toISOString()}\nLast read: ${time.toISOString()}\nDelta: ${deltaMs}ms (tolerance: ${toleranceMs}ms)\n\nPlease read the file again before modifying it.`,
       )
     }
+    // altimate_change end
   }
 }

packages/opencode/test/file/time.test.ts

@@ -112,7 +112,9 @@ describe("file/time", () => {
         fn: async () => {
           FileTime.read(sessionID, filepath)
 
-          // Modify file and set mtime 5s in the future to exceed 2s tolerance
+          // Simulate external modification by setting mtime 5s ahead of the
+          // file's current mtime (read() stores mtime, assert() compares
+          // against current mtime — both from filesystem clock).
           await fs.writeFile(filepath, "modified content", "utf-8")
           const future = new Date(Date.now() + 5000)
           await fs.utimes(filepath, future, future)
@@ -122,7 +124,7 @@ describe("file/time", () => {
       })
     })
 
-    test("includes timestamps in error message", async () => {
+    test("includes timestamps and delta in error message", async () => {
       await using tmp = await tmpdir()
       const filepath = path.join(tmp.path, "file.txt")
       await fs.writeFile(filepath, "content", "utf-8")
@@ -132,7 +134,6 @@ describe("file/time", () => {
         fn: async () => {
           FileTime.read(sessionID, filepath)
           await fs.writeFile(filepath, "modified", "utf-8")
-          // Set mtime 5 seconds in the future to exceed the 2s tolerance
           const future = new Date(Date.now() + 5000)
           await fs.utimes(filepath, future, future)
 
@@ -145,6 +146,8 @@ describe("file/time", () => {
           expect(error).toBeDefined()
           expect(error!.message).toContain("Last modification:")
           expect(error!.message).toContain("Last read:")
+          expect(error!.message).toContain("Delta:")
+          expect(error!.message).toContain("tolerance:")
         },
       })
     })
@@ -347,8 +350,8 @@ describe("file/time", () => {
 
           const originalStat = Filesystem.stat(filepath)
 
+          // Simulate external modification with mtime far ahead
           await fs.writeFile(filepath, "modified", "utf-8")
-          // Set mtime 5 seconds in the future to exceed the 2s tolerance
           const future = new Date(Date.now() + 5000)
           await fs.utimes(filepath, future, future)
 
@@ -359,5 +362,23 @@ describe("file/time", () => {
         },
       })
     })
+
+    test("read() stores filesystem mtime, not wall-clock time", async () => {
+      await using tmp = await tmpdir()
+      const filepath = path.join(tmp.path, "file.txt")
+      await fs.writeFile(filepath, "content", "utf-8")
+
+      await Instance.provide({
+        directory: tmp.path,
+        fn: async () => {
+          const statBefore = Filesystem.stat(filepath)
+          FileTime.read(sessionID, filepath)
+          const readTime = FileTime.get(sessionID, filepath)
+
+          // read() should store the file's mtime, not wall-clock
+          expect(readTime!.getTime()).toBe(statBefore!.mtime.getTime())
+        },
+      })
+    })
   })
 })

packages/opencode/test/tool/edit.test.ts

@@ -239,7 +239,7 @@ describe("tool.edit", () => {
           FileTime.read(ctx.sessionID, filepath)
 
           // Simulate external modification with mtime 5s in the future
-          // to exceed the 2s tolerance in FileTime.assert()
+          // to exceed the 50ms tolerance in FileTime.assert()
           await fs.writeFile(filepath, "modified externally", "utf-8")
           const future = new Date(Date.now() + 5000)
           await fs.utimes(filepath, future, future)