fix(session-logs): preserve output arrival timestamps through flushes

electron/bridges/sessionLogStreamManager.cjs

@@ -28,38 +28,8 @@ const SUDO_AUTOFILL_REWRITE_PATTERN =
 function formatLogTimestamp(timestamp = Date.now()) {
   const date = new Date(timestamp);
   const pad = (n) => String(n).padStart(2, "0");
-  return `${date.getFullYear()}-${pad(date.getMonth() + 1)}-${pad(date.getDate())} ${pad(date.getHours())}:${pad(date.getMinutes())}:${pad(date.getSeconds())}`;
-}
-
-function createRenderedLineTimestampPrefixer(opts = {}) {
-  const timestampProvider = typeof opts.timestampProvider === "function"
-    ? opts.timestampProvider
-    : Date.now;
-  const timestampsByLine = [];
-  const contentByLine = [];
-
-  return (content) => {
-    if (!content) return "";
-
-    const lines = content.split("\n");
-    timestampsByLine.length = lines.length;
-    contentByLine.length = lines.length;
-
-    return lines.map((line, index) => {
-      if (line.length === 0 && index === lines.length - 1 && content.endsWith("\n")) {
-        return line;
-      }
-
-      if (contentByLine[index] !== line) {
-        contentByLine[index] = line;
-        timestampsByLine[index] = timestampProvider() ?? Date.now();
-      }
-
-      return line.length === 0
-        ? line
-        : `[${formatLogTimestamp(timestampsByLine[index])}] ${line}`;
-    }).join("\n");
-  };
+  // Millisecond precision so sub-second timings stay visible in logs (#3414).
+  return `${date.getFullYear()}-${pad(date.getMonth() + 1)}-${pad(date.getDate())} ${pad(date.getHours())}:${pad(date.getMinutes())}:${pad(date.getSeconds())}.${String(date.getMilliseconds()).padStart(3, "0")}`;
 }
 
 function parseSudoAutofillRewrite(input) {
@@ -217,9 +187,11 @@ function createStreamEntry(sessionId, opts) {
     renderer: isRaw ? null : createTerminalTextRenderer({
       alternateScreenActive: opts.alternateScreenActive === true,
     }),
-    renderedTimestampPrefixer: !isRaw && opts.timestampsEnabled
-      ? createRenderedLineTimestampPrefixer({ timestampProvider: opts.timestampProvider })
+    timestampProvider: !isRaw && opts.timestampsEnabled
+      ? (opts.timestampProvider ?? Date.now)
       : null,
+    timestampedChunks: [],
+    lastArrivalTime: undefined,
     hostLabel,
     startTime,
     buffer: "",
@@ -297,7 +269,14 @@ function flushBuffer(entry) {
     if (entry.isRaw) {
       entry.writeStream.write(data);
     } else {
-      entry.renderer.feed(data);
+      if (entry.timestampProvider) {
+        for (const chunk of entry.timestampedChunks) {
+          entry.renderer.feed(chunk.data, chunk.timestamp);
+        }
+        entry.timestampedChunks = [];
+      } else {
+        entry.renderer.feed(data);
+      }
       entry.snapshotDirty = true;
       scheduleSnapshot(entry);
     }
@@ -324,13 +303,16 @@ function registerProgrammaticCommandLogRewrite(sessionId, rewrite) {
 
 function renderSnapshotContent(entry, { finalize = false } = {}) {
   if (finalize) entry.renderer.finish();
-  const renderOptions = finalize ? undefined : { includePendingClearedScreen: true };
+  const renderOptions = {
+    includePendingClearedScreen: !finalize,
+    formatLine: entry.timestampProvider
+      ? (line, timestamp) => line ? `[${formatLogTimestamp(timestamp)}] ${line}` : line
+      : undefined,
+  };
   const renderedContent = entry.isHtml
     ? entry.renderer.toHtmlContent(renderOptions)
     : entry.renderer.toString(renderOptions);
-  const content = entry.renderedTimestampPrefixer
-    ? entry.renderedTimestampPrefixer(renderedContent)
-    : renderedContent;
+  const content = renderedContent;
   return entry.isHtml
     ? wrapTerminalHtmlContent(content, entry.hostLabel, entry.startTime)
     : content;
@@ -395,10 +377,13 @@ function appendData(sessionId, dataChunk) {
 }
 
 function appendBufferedData(entry, dataChunk) {
+  if (entry.timestampProvider && dataChunk) {
+    entry.lastArrivalTime = entry.timestampProvider() ?? Date.now();
+  }
   const readableData = entry.programmaticCommandLogRewriter
     ? entry.programmaticCommandLogRewriter.append(dataChunk)
     : dataChunk;
-  entry.buffer += sanitizeSudoAutofillLogData(entry, readableData);
+  bufferReadableData(entry, sanitizeSudoAutofillLogData(entry, readableData));
 
   // Immediate flush if buffer is large
   if (entry.buffer.length + entry.sudoAutofillPending.length >= MAX_BUFFER_SIZE) {
@@ -406,6 +391,16 @@ function appendBufferedData(entry, dataChunk) {
   }
 }
 
+// Preserve each sanitized chunk's receipt time through the periodic disk flush.
+// A command held by a rewriter uses the time of the chunk that completes it.
+function bufferReadableData(entry, data) {
+  if (!data) return;
+  entry.buffer += data;
+  if (entry.timestampProvider) {
+    entry.timestampedChunks.push({ data, timestamp: entry.lastArrivalTime });
+  }
+}
+
 /**
  * Stop the log stream for a session.
  * Flushes remaining data, closes the write stream, and finalizes the file.
@@ -450,9 +445,9 @@ async function stopStream(sessionId, expectedToken) {
   }
   const readablePending = entry.programmaticCommandLogRewriter?.finish();
   if (readablePending) {
-    entry.buffer += sanitizeSudoAutofillLogData(entry, readablePending);
+    bufferReadableData(entry, sanitizeSudoAutofillLogData(entry, readablePending));
   }
-  entry.buffer += sanitizeSudoAutofillLogData(entry, "", { final: true });
+  bufferReadableData(entry, sanitizeSudoAutofillLogData(entry, "", { final: true }));
   flushBuffer(entry);
   await waitForSnapshotIdle(entry);
 

electron/bridges/sessionLogStreamManager.test.cjs

@@ -708,9 +708,9 @@ test("txt stream timestamps complete lines without duplicating split chunks", as
   const directory = path.join(TEMP_ROOT, `stream-timestamps-${Date.now()}-${Math.random().toString(16).slice(2)}`);
   const sessionId = `session-${Date.now()}-${Math.random().toString(16).slice(2)}`;
   const times = [
-    new Date(2026, 0, 2, 3, 4, 5).getTime(),
-    new Date(2026, 0, 2, 3, 4, 6).getTime(),
-    new Date(2026, 0, 2, 3, 4, 7).getTime(),
+    new Date(2026, 0, 2, 3, 4, 5, 123).getTime(),
+    new Date(2026, 0, 2, 3, 4, 6, 456).getTime(),
+    new Date(2026, 0, 2, 3, 4, 7, 89).getTime(),
   ];
 
   try {
@@ -730,7 +730,7 @@ test("txt stream timestamps complete lines without duplicating split chunks", as
 
     assert.equal(
       fs.readFileSync(filePath, "utf8"),
-      "[2026-01-02 03:04:05] first line\n[2026-01-02 03:04:06] second line\n[2026-01-02 03:04:07] partial",
+      "[2026-01-02 03:04:06.456] first line\n[2026-01-02 03:04:06.456] second line\n[2026-01-02 03:04:06.456] partial",
     );
   } finally {
     await stopStream(sessionId);
@@ -758,7 +758,7 @@ test("txt stream timestamps rendered lines after carriage-return rewrites", asyn
 
     assert.equal(
       fs.readFileSync(filePath, "utf8"),
-      "[2026-01-02 03:04:05] docker denied",
+      "[2026-01-02 03:04:05.000] docker denied",
     );
   } finally {
     await stopStream(sessionId);
@@ -785,14 +785,14 @@ test("txt stream updates a line timestamp when a later snapshot rewrites that li
       timestampProvider: () => times.shift(),
     });
     appendData(sessionId, "old prompt");
-    await waitForFileContent(directory, "[2026-01-02 03:04:05] old prompt");
+    await waitForFileContent(directory, "[2026-01-02 03:04:05.000] old prompt");
     appendData(sessionId, "\rdocker denied");
 
     const filePath = await stopStream(sessionId);
 
     assert.equal(
       fs.readFileSync(filePath, "utf8"),
-      "[2026-01-02 03:04:06] docker denied",
+      "[2026-01-02 03:04:06.000] docker denied",
     );
   } finally {
     await stopStream(sessionId);
@@ -819,7 +819,7 @@ test("html stream includes line timestamps in rendered content", async () => {
     const filePath = await stopStream(sessionId);
     const html = fs.readFileSync(filePath, "utf8");
 
-    assert.match(html, /\[2026-01-02 03:04:05\] line/);
+    assert.match(html, /\[2026-01-02 03:04:05\.000\] line/);
   } finally {
     await stopStream(sessionId);
     fs.rmSync(directory, { recursive: true, force: true });
@@ -845,7 +845,7 @@ test("html stream timestamps rendered lines after carriage-return rewrites", asy
     const filePath = await stopStream(sessionId);
     const html = fs.readFileSync(filePath, "utf8");
 
-    assert.match(html, /\[2026-01-02 03:04:05\] docker denied/);
+    assert.match(html, /\[2026-01-02 03:04:05\.000\] docker denied/);
     assert.doesNotMatch(html, /old prompt/);
   } finally {
     await stopStream(sessionId);
@@ -904,3 +904,28 @@ function findFirstTxtFile(directory) {
   }
   return null;
 }
+
+for (const format of ["txt", "html"]) {
+  test(`${format} timestamps preserve arrival gaps inside one flush interval`, async () => {
+    const directory = path.join(TEMP_ROOT, `arrival-${format}-${Date.now()}`);
+    const sessionId = `arrival-${format}`;
+    let now = new Date(2026, 0, 2, 3, 4, 5, 89).getTime();
+    try {
+      startStream(sessionId, {
+        hostLabel: "host", directory, format, timestampsEnabled: true,
+        timestampProvider: () => now,
+      });
+      appendData(sessionId, "first\r\n");
+      now += 300;
+      appendData(sessionId, "second\r\n");
+      now += 100;
+      const filePath = await stopStream(sessionId);
+      const content = fs.readFileSync(filePath, "utf8");
+      assert.match(content, /\[2026-01-02 03:04:05\.089\] first/);
+      assert.match(content, /\[2026-01-02 03:04:05\.389\] second/);
+    } finally {
+      await stopStream(sessionId);
+      fs.rmSync(directory, { recursive: true, force: true });
+    }
+  });
+}

electron/bridges/sessionLogsBridge.test.cjs

@@ -642,7 +642,7 @@ test("manual session logs honor HTML format and timestamps", async () => {
     assert.match(content, /<!DOCTYPE html>/);
     assert.match(content, /HTML \/ host:22/);
     assert.doesNotMatch(content, /HTML _ host_22/);
-    assert.match(content, /\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\] ready/);
+    assert.match(content, /\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3}\] ready/);
   } finally {
     await sessionLogStreamManager.cleanupAll();
     fs.rmSync(directory, { recursive: true, force: true });

electron/bridges/terminalLogSanitizer.cjs

@@ -60,8 +60,9 @@ class TerminalTextRenderer {
     this.alternateScreenActive = options.alternateScreenActive === true;
   }
 
-  feed(input) {
+  feed(input, timestamp) {
     if (!input) return;
+    this.timestamp = timestamp;
 
     for (const ch of input) {
       this.#consume(ch);
@@ -75,18 +76,18 @@ class TerminalTextRenderer {
     return this.toString();
   }
 
-  toString({ includePendingClearedScreen = false } = {}) {
+  toString({ includePendingClearedScreen = false, formatLine = (line) => line } = {}) {
     const lines = includePendingClearedScreen ? this.#linesWithPendingClearedScreen() : this.lines;
     return lines
-      .map((line) => line.map((cell) => cell?.ch || " ").join("").replace(/[ \t]+$/g, ""))
+      .map((line) => formatLine(line.map((cell) => cell?.ch || " ").join("").replace(/[ \t]+$/g, ""), line.timestamp))
       .join("\n")
       .replace(/\n+$/g, "");
   }
 
-  toHtmlContent({ includePendingClearedScreen = false } = {}) {
+  toHtmlContent({ includePendingClearedScreen = false, formatLine = (line) => line } = {}) {
     const lines = includePendingClearedScreen ? this.#linesWithPendingClearedScreen() : this.lines;
     return lines
-      .map((line) => renderLineHtml(line))
+      .map((line) => formatLine(renderLineHtml(line), line.timestamp))
       .join("\n")
       .replace(/\n+$/g, "");
   }
@@ -347,6 +348,7 @@ class TerminalTextRenderer {
   #writeText(text) {
     this.#ensureLine();
     const line = this.lines[this.row];
+    if (this.timestamp !== undefined) line.timestamp = this.timestamp;
     while (line.length < this.col) line.push(createCell(" ", createDefaultStyle()));
     for (const ch of text) {
       line[this.col] = createCell(ch, this.style);
@@ -359,6 +361,12 @@ class TerminalTextRenderer {
   #eraseLine(mode) {
     this.#ensureLine();
     const line = this.lines[this.row];
+    const changesContent = mode === 1
+      ? line.slice(0, Math.min(this.col + 1, getTrimmedLineLength(line))).some((cell) =>
+        cell && (cell.ch !== " " || !stylesEqual(cell.style, createDefaultStyle()))
+      )
+      : mode === 2 ? getTrimmedLineLength(line) > 0 : this.col < getTrimmedLineLength(line);
+    if (changesContent && this.timestamp !== undefined) line.timestamp = this.timestamp;
     if (mode === 1) {
       for (let i = 0; i <= this.col && i < line.length; i += 1) {
         line[i] = createCell(" ", createDefaultStyle());
@@ -541,7 +549,11 @@ function createCell(ch, style) {
 }
 
 function cloneLines(lines) {
-  return lines.map((line) => line.map((cell) => (cell ? createCell(cell.ch, cell.style) : cell)));
+  return lines.map((line) => {
+    const clone = line.map((cell) => (cell ? createCell(cell.ch, cell.style) : cell));
+    if (line.timestamp !== undefined) clone.timestamp = line.timestamp;
+    return clone;
+  });
 }
 
 function trimTrailingBlankLines(lines) {

electron/bridges/terminalLogSanitizer.test.cjs

@@ -288,3 +288,45 @@ test("explicit backgrounds preserve original foreground/background pairs across
   assert.match(html, /color: #1e1e1e; background-color: #cd3131[^>]*>inverse/);
   assert.match(html, /color: #d4d4d4; background-color: #000000[^>]*>RGB background/);
 });
+
+test("line timestamps follow writes, erasure and preserved cleared screens", () => {
+  const renderer = createTerminalTextRenderer();
+  const formatLine = (line, timestamp) => line ? `[${timestamp}] ${line}` : line;
+  renderer.feed("before tui\n", 89);
+  renderer.feed("\x1b[H\x1b[2Jframe one\n", 389);
+  renderer.feed("\x1b[H\x1b[2Jframe two\n", 489);
+  const expected = "[89] before tui\n\n[389] frame one\n\n[489] frame two";
+  assert.equal(renderer.toString({ includePendingClearedScreen: true, formatLine }), expected);
+  renderer.finish();
+  assert.equal(renderer.toString({ formatLine }), expected);
+  assert.equal(renderer.toHtmlContent({ formatLine }), expected);
+});
+
+test("line timestamps track split ANSI writes and partial line erasure", () => {
+  const renderer = createTerminalTextRenderer();
+  const formatLine = (line, timestamp) => line ? `[${timestamp}] ${line}` : line;
+  renderer.feed("unchanged\r\nlong tail", 89);
+  renderer.feed("\r\x1b[", 389);
+  renderer.feed("31mshort\x1b[K", 489);
+  assert.equal(renderer.toString({ formatLine }), "[89] unchanged\n[489] short");
+  assert.match(renderer.toHtmlContent({ formatLine }), /\[489\] <span[^>]*>short<\/span>/);
+});
+
+test("no-op line erasure preserves the output timestamp", () => {
+  const renderer = createTerminalTextRenderer();
+  const formatLine = (line, timestamp) => line ? `[${timestamp}] ${line}` : line;
+  renderer.feed("completed", 1000);
+  renderer.feed("\x1b[K", 9000);
+  assert.equal(renderer.toString({ formatLine }), "[1000] completed");
+  renderer.feed("\r\x1b[4C\x1b[K", 10000);
+  assert.equal(renderer.toString({ formatLine }), "[10000] comp");
+});
+
+test("erasing styled spaces updates the visible line timestamp", () => {
+  const renderer = createTerminalTextRenderer();
+  const formatLine = (line, timestamp) => line ? `[${timestamp}] ${line}` : line;
+  renderer.feed("\x1b[41m   \x1b[0mtext", 1000);
+  assert.match(renderer.toHtmlContent({ formatLine }), /background-color/);
+  renderer.feed("\r\x1b[2C\x1b[1K", 9000);
+  assert.equal(renderer.toHtmlContent({ formatLine }), "[9000]    text");
+});