feat(drive): add --debug NDJSON sync log to drive watch

src/handwritten/commands/drive/api.ts

@@ -29,6 +29,10 @@ async function expectJsonResult<T>(result: JsonResult<T>): Promise<T> {
   return result.data
 }
 
+// Lets the server attribute drive file operations to the sync loop instead
+// of generic API traffic (drive_file_operation actor: "sync" vs "api").
+const SYNC_CLIENT_HEADERS = { "x-wspc-client": "drive-sync" } as const
+
 function driveContentUrl(baseUrl: string, id: string): URL {
   const baseWithTrailingSlash = baseUrl.endsWith("/") ? baseUrl : `${baseUrl}/`
   return new URL(`drive/libraries/${encodeURIComponent(id)}/files/content`, baseWithTrailingSlash)
@@ -58,6 +62,7 @@ export async function createDriveApi(opts: DriveApiOptions = {}) {
       const result = await driveFileDelete({
         client: rawClient,
         path: { id },
+        headers: SYNC_CLIENT_HEADERS,
         body: {
           path,
           expected_entry_version: expectedEntryVersion,
@@ -83,6 +88,7 @@ export async function createDriveApi(opts: DriveApiOptions = {}) {
         headers: {
           "content-type": "application/octet-stream",
           "x-drive-content-sha256": sha256,
+          ...SYNC_CLIENT_HEADERS,
         },
         body,
       })

src/handwritten/commands/drive/debug-log.ts

@@ -0,0 +1,45 @@
+import { appendFileSync, mkdirSync, renameSync, statSync } from "node:fs"
+import { join } from "node:path"
+import { driveIsoTimestamp, systemDriveClock, type DriveClock } from "./clock.js"
+import { DRIVE_DIR } from "./state.js"
+
+export interface DriveDebugLogger {
+  log(event: string, fields?: Record<string, unknown>): void
+}
+
+export const noopDriveDebugLogger: DriveDebugLogger = { log() {} }
+
+export const DEBUG_LOG_FILE = "debug.log"
+const MAX_DEBUG_LOG_BYTES = 10 * 1024 * 1024
+
+export function createDriveDebugLogger(
+  root: string,
+  options: { clock?: DriveClock; maxBytes?: number } = {},
+): DriveDebugLogger {
+  const clock = options.clock ?? systemDriveClock
+  const maxBytes = options.maxBytes ?? MAX_DEBUG_LOG_BYTES
+  const dir = join(root, DRIVE_DIR)
+  const file = join(dir, DEBUG_LOG_FILE)
+  let warned = false
+  return {
+    log(event, fields = {}) {
+      // Debug logging must never break sync; failures are swallowed after a
+      // single stderr warning.
+      try {
+        mkdirSync(dir, { recursive: true })
+        try {
+          if (statSync(file).size > maxBytes) renameSync(file, `${file}.old`)
+        } catch {
+          // File missing or unreadable; append below decides the outcome.
+        }
+        appendFileSync(file, `${JSON.stringify({ ts: driveIsoTimestamp(clock), event, ...fields })}\n`)
+      } catch (error) {
+        if (!warned) {
+          warned = true
+          const message = error instanceof Error ? error.message : String(error)
+          process.stderr.write(`wspc drive: debug log write failed: ${message}\n`)
+        }
+      }
+    },
+  }
+}

src/handwritten/commands/drive/sync.ts

@@ -3,6 +3,7 @@ import { mkdir, readFile, rm, writeFile } from "node:fs/promises"
 import { basename, dirname, join, posix as pathPosix, resolve } from "node:path"
 import { createHash, randomUUID } from "node:crypto"
 import { createDriveApi } from "./api.js"
+import { noopDriveDebugLogger, type DriveDebugLogger } from "./debug-log.js"
 import { driveConflictTimestamp, driveIsoTimestamp, systemDriveClock, type DriveClock } from "./clock.js"
 import { decideDriveAction, type DriveAction } from "./decision.js"
 import { normalizeRemoteManifest } from "./manifest.js"
@@ -89,18 +90,23 @@ export async function runDriveSyncOnce(
   api?: DriveSyncApi,
   clock: DriveClock = systemDriveClock,
   onProgress?: DriveSyncProgress,
+  debug: DriveDebugLogger = noopDriveDebugLogger,
 ): Promise<DriveSyncSummary> {
   return withDriveLock(root, async () => {
     let state = await readDriveState(root)
     const syncApi = api ?? (await createDriveApi())
     const summary = emptySummary()
     const blockedPaths = new Set<string>()
+    const scanStartedMs = Date.now()
     const localFiles = await scanDriveFiles(root, {
       onPathError: async (path, error) => {
         await recordPathError(summary, blockedPaths, path, error)
       },
     })
+    const scanMs = Date.now() - scanStartedMs
+    const manifestStartedMs = Date.now()
     const remoteFiles = await fetchRemoteManifest(root, state, syncApi, summary, blockedPaths)
+    const manifestMs = Date.now() - manifestStartedMs
     const paths = Array.from(
       new Set([...Object.keys(localFiles), ...Object.keys(remoteFiles), ...Object.keys(state.entries)]),
     )
@@ -115,11 +121,27 @@ export async function runDriveSyncOnce(
     let processed = 0
     onProgress?.(processed, total)
 
+    const processStartedMs = Date.now()
     for (const path of paths) {
       const remote = remoteFiles[path]
-      const action = decideDriveAction(state.entries[path], localFiles[path], remote)
-      const result = await processPath({ root, state, api: syncApi, path, action, remote, local: localFiles[path], summary, clock })
+      const local = localFiles[path]
+      const action = decideDriveAction(state.entries[path], local, remote)
+      if (isActionableAction(action)) {
+        debug.log("decision", decisionFields(path, action, state.entries[path], local, remote))
+      }
+      const previousConflict = state.conflicts[path]
+      const result = await processPath({ root, state, api: syncApi, path, action, remote, local, summary, clock })
       state = result.state
+      const recordedConflict = state.conflicts[path]
+      if (recordedConflict !== undefined && recordedConflict !== previousConflict) {
+        debug.log("conflict", {
+          path,
+          reason: recordedConflict.reason,
+          ...(recordedConflict.type === undefined ? {} : { type: recordedConflict.type }),
+          ...(recordedConflict.strategy === undefined ? {} : { strategy: recordedConflict.strategy }),
+          ...(recordedConflict.conflict_paths === undefined ? {} : { conflict_paths: recordedConflict.conflict_paths }),
+        })
+      }
       if (isActionableAction(action)) {
         processed += 1
         onProgress?.(processed, total)
@@ -128,10 +150,32 @@ export async function runDriveSyncOnce(
     }
 
     recordUnresolvedConflicts(summary, state)
+    debug.log("sync_phases", { scan_ms: scanMs, manifest_ms: manifestMs, process_ms: Date.now() - processStartedMs })
     return summary
   })
 }
 
+function decisionFields(
+  path: string,
+  action: DriveAction,
+  entry: DriveStateEntry | undefined,
+  local: { sha256: string; size_bytes: number } | undefined,
+  remote: RemoteEntry | undefined,
+): Record<string, unknown> {
+  return {
+    path,
+    action: action.type,
+    ...("reason" in action && action.reason !== undefined ? { reason: action.reason } : {}),
+    ...(entry === undefined
+      ? {}
+      : { base_version_id: entry.current_version_id, base_entry_version: entry.entry_version, base_sha256: entry.content_sha256 }),
+    ...(local === undefined ? {} : { local_sha256: local.sha256, local_size_bytes: local.size_bytes }),
+    ...(remote === undefined
+      ? {}
+      : { remote_version_id: remote.current_version_id, remote_entry_version: remote.entry_version, remote_sha256: remote.content_sha256 }),
+  }
+}
+
 export function driveSyncCommand(api?: DriveSyncApi): Command {
   const sync = new Command("sync").description("Drive sync commands")
   sync

src/handwritten/commands/drive/watch.ts

@@ -4,6 +4,7 @@ import { watch as fsWatch } from "node:fs"
 import { relative, resolve } from "node:path"
 import { loadRealtimeAuthHeaders } from "../../auth/load-sdk-client.js"
 import { render, shouldOutputJson } from "../../output/render.js"
+import { createDriveDebugLogger, noopDriveDebugLogger, type DriveDebugLogger } from "./debug-log.js"
 import { createDriveRealtimeSource } from "./realtime.js"
 import { DRIVE_DIR, ensureDriveRealtimeState, readDriveState, writeDriveRealtimeState } from "./state.js"
 import { runDriveSyncOnce, type DriveSyncProgress, type DriveSyncSummary } from "./sync.js"
@@ -39,12 +40,15 @@ export interface DriveWatchOptions {
   debounceMs?: number
   remoteDebounceMs?: number
   onEvent?: (event: unknown) => void
+  debug?: boolean
+  debugLogger?: DriveDebugLogger
 }
 
 export async function runDriveWatch(root: string, options: DriveWatchOptions = {}): Promise<void> {
+  const dbg = options.debugLogger ?? (options.debug ? createDriveDebugLogger(root) : noopDriveDebugLogger)
   const runSync =
     options.runSync ??
-    ((syncRoot: string, onProgress?: DriveSyncProgress) => runDriveSyncOnce(syncRoot, undefined, undefined, onProgress))
+    ((syncRoot: string, onProgress?: DriveSyncProgress) => runDriveSyncOnce(syncRoot, undefined, undefined, onProgress, dbg))
   const debounceMs = options.debounceMs ?? 500
   const remoteDebounceMs = options.remoteDebounceMs ?? 2000
   // Watch is a long-lived event stream: json mode must emit NDJSON (one event
@@ -59,6 +63,7 @@ export async function runDriveWatch(root: string, options: DriveWatchOptions = {
       }
       render({ kind: "drive_watch", display: { shape: "object" } }, event)
     })
+  let nextTrigger = "initial"
   let debounceTimer: NodeJS.Timeout | undefined
   let debounceDeadlineMs: number | undefined
   let retryTimer: NodeJS.Timeout | undefined
@@ -85,14 +90,28 @@ export async function runDriveWatch(root: string, options: DriveWatchOptions = {
           // A large first upload can run for minutes; without this the app
           // shows a stale badge and users assume sync never started.
           emit({ kind: "drive_sync_start" })
+          dbg.log("sync_start", { trigger: nextTrigger })
+          const startedAtMs = Date.now()
           const summary = await runSync(root, (processed, total) => {
             emit({ kind: "drive_sync_progress", processed, total })
           })
           emit({ kind: "drive_sync_once", ...summary })
+          dbg.log("sync_end", {
+            duration_ms: Date.now() - startedAtMs,
+            uploaded: summary.uploaded,
+            downloaded: summary.downloaded,
+            deleted: summary.deleted,
+            merged: summary.merged,
+            unchanged: summary.unchanged,
+            conflicts: summary.conflicts,
+            errors: summary.errors,
+          })
           backoffMs = 1000
         } catch (error) {
           if (isAuthError(error) || isFatalWatchError(error) || !isRetryableWatchError(error)) throw error
           emit({ kind: "drive_watch_retry", delay_ms: backoffMs, error: errorMessage(error) })
+          dbg.log("retry", { delay_ms: backoffMs, error: errorMessage(error) })
+          nextTrigger = "retry"
           if (stopped) return
           await waitForManagedTimer(backoffMs)
           if (stopped) return
@@ -112,7 +131,8 @@ export async function runDriveWatch(root: string, options: DriveWatchOptions = {
     debounceDeadlineMs = undefined
   }
 
-  function scheduleSync(delayMs: number): void {
+  function scheduleSync(delayMs: number, trigger: string): void {
+    nextTrigger = trigger
     if (running) {
       rerunRequested = true
       return
@@ -187,7 +207,8 @@ export async function runDriveWatch(root: string, options: DriveWatchOptions = {
     source = options.source ?? createDefaultWatchSource(root)
     source.onChange((path) => {
       if (isDriveInternalPath(root, path)) return
-      scheduleSync(debounceMs)
+      dbg.log("fs_event", { path: relative(root, path) })
+      scheduleSync(debounceMs, "local")
     })
 
     emit({ kind: "drive_watch_started", root, library_id: state.library_id })
@@ -198,11 +219,12 @@ export async function runDriveWatch(root: string, options: DriveWatchOptions = {
         },
         onEvent(event) {
           emit(realtimeEvent(event))
+          dbg.log("realtime_event", { ...event })
           if (event.immediate) {
-            scheduleSync(0)
+            scheduleSync(0, "remote")
             return
           }
-          scheduleSync(event.debounce_ms ?? remoteDebounceMs)
+          scheduleSync(event.debounce_ms ?? remoteDebounceMs, "remote")
         },
         onReconnect(delayMs, error) {
           emit({ kind: "drive_realtime_reconnecting", delay_ms: delayMs, error })
@@ -236,8 +258,10 @@ export function driveWatchCommand(options: DriveWatchOptions = {}): Command {
   return new Command("watch")
     .description("Watch a bound Drive folder and sync local changes")
     .argument("[path]", "local folder path", ".")
-    .action(async (path: string) => {
-      await runDriveWatch(resolve(path), options)
+    .option("--debug", "append debug NDJSON events to <folder>/.wspc-drive/debug.log")
+    .action(async (path: string, flags: { debug?: boolean }) => {
+      const debug = options.debug ?? (flags.debug === true || process.env.WSPC_DRIVE_DEBUG === "1")
+      await runDriveWatch(resolve(path), { ...options, debug })
     })
 }
 

test/handwritten/drive/api.test.ts

@@ -146,6 +146,25 @@ describe("createDriveApi", () => {
     expect(fetchImpl).toHaveBeenCalledOnce()
   })
 
+  it("uploadFile and deleteFile identify the sync client via x-wspc-client", async () => {
+    const seenHeaders: Array<string | null> = []
+    const fetchImpl = vi.fn(async (input: RequestInfo | URL, init?: RequestInit) => {
+      const req = mkReq(input, init)
+      seenHeaders.push(req.headers.get("x-wspc-client"))
+      const payload = req.method === "PUT" ? DRIVE_UPLOAD : DRIVE_DELETE
+      return new Response(JSON.stringify(payload), {
+        status: 200,
+        headers: { "content-type": "application/json" },
+      })
+    }) as typeof fetch
+
+    const api = await mkDriveApi(fetchImpl)
+    await api.uploadFile("lib_1", "notes/hello.txt", new TextEncoder().encode("hello"), "3a6eb7", 2)
+    await api.deleteFile("lib_1", "notes/hello.txt", 2)
+
+    expect(seenHeaders).toEqual(["drive-sync", "drive-sync"])
+  })
+
   it("throws useful errors for failed JSON SDK calls", async () => {
     const fetchImpl = vi.fn(async () =>
       new Response(JSON.stringify({ error: { code: "SERVER_ERROR", message: "boom" } }), {