Trace git command spawn and close metadata

Thread an optional logger through runGitCommand and the CheckoutContext helpers so workspace-git-service can emit trace-level traces around each git invocation. Behavior is unchanged when no logger is supplied.
2026-07-29 12:01:31 +00:00 · 2026-05-15 09:49:43 +07:00
parent f27d39fb63
commit 2d3c9101f3
4 changed files with 162 additions and 24 deletions
--- a/packages/server/src/server/workspace-git-service.ts
+++ b/packages/server/src/server/workspace-git-service.ts
@@ -421,6 +421,7 @@ export class WorkspaceGitServiceImpl implements WorkspaceGitService {
    try {
      const status = await this.deps.getCheckoutStatus(normalizedCwd, {
        paseoHome: this.paseoHome,
+        logger: this.logger,
      });
      if (!status.isGit) {
        return checkoutLiteFromGitSnapshot(normalizedCwd, {
@@ -1491,7 +1492,7 @@ export class WorkspaceGitServiceImpl implements WorkspaceGitService {
    }

    const cwd = target.cwd;
-    const context: CheckoutContext = { paseoHome: this.paseoHome };
+    const context: CheckoutContext = { paseoHome: this.paseoHome, logger: this.logger };
    const checkoutStatus = await this.deps.getCheckoutStatus(cwd, context);
    if (!checkoutStatus.isGit) {
      target.latestSnapshotLoadedAtMs = now.getTime();
--- a/packages/server/src/utils/checkout-git.ts
+++ b/packages/server/src/utils/checkout-git.ts
@@ -2,6 +2,7 @@ import { resolve, dirname, basename } from "path";
 import { existsSync, realpathSync } from "fs";
 import { open as openFile, readFile, stat as statFile } from "fs/promises";
 import { TTLCache } from "@isaacs/ttlcache";
+import type { Logger } from "pino";
 import type { ParsedDiffFile } from "../server/utils/diff-highlighter.js";
 import { parseAndHighlightDiff } from "../server/utils/diff-highlighter.js";
 import { parseGitHubRepoFromRemote } from "../server/workspace-git-metadata.js";
@@ -712,6 +713,7 @@ export interface MergeFromBaseOptions {

 export interface CheckoutContext {
  paseoHome?: string;
+  logger?: Pick<Logger, "trace">;
 }

 function isGitError(error: unknown): boolean {
@@ -767,11 +769,12 @@ async function getRebaseHeadBranch(cwd: string): Promise<string | null> {
  return results.find((result): result is string => result !== null) ?? null;
 }

-async function getWorktreeRoot(cwd: string): Promise<string | null> {
+async function getWorktreeRoot(cwd: string, context?: CheckoutContext): Promise<string | null> {
  try {
    const { stdout } = await runGitCommand(["rev-parse", "--show-toplevel"], {
      cwd,
      envOverlay: READ_ONLY_GIT_ENV,
+      logger: context?.logger,
    });
    return parseGitRevParsePath(stdout);
  } catch {
@@ -960,10 +963,11 @@ async function resolveBaseRefForCwd(
  };
 }

-async function isWorkingTreeDirty(cwd: string): Promise<boolean> {
+async function isWorkingTreeDirty(cwd: string, context?: CheckoutContext): Promise<boolean> {
  const { stdout } = await runGitCommand(["status", "--porcelain"], {
    cwd,
    envOverlay: READ_ONLY_GIT_ENV,
+    logger: context?.logger,
  });
  return stdout.trim().length > 0;
 }
@@ -986,11 +990,16 @@ export async function hasOriginRemote(cwd: string): Promise<boolean> {
  return url !== null;
 }

-async function getGitConfigValue(cwd: string, key: string): Promise<string | null> {
+async function getGitConfigValue(
+  cwd: string,
+  key: string,
+  context?: CheckoutContext,
+): Promise<string | null> {
  try {
    const { stdout } = await runGitCommand(["config", "--get", key], {
      cwd,
      envOverlay: READ_ONLY_GIT_ENV,
+      logger: context?.logger,
    });
    const value = stdout.trim();
    return value.length > 0 ? value : null;
@@ -1151,20 +1160,29 @@ function normalizeComparisonBaseRefName(input: string): ComparisonBaseRefName {
  return { localName, originRef: `origin/${localName}` };
 }

-async function doesGitRefExist(cwd: string, fullRef: string): Promise<boolean> {
+async function doesGitRefExist(
+  cwd: string,
+  fullRef: string,
+  context?: CheckoutContext,
+): Promise<boolean> {
  const result = await runGitCommand(["show-ref", "--verify", "--quiet", fullRef], {
    cwd,
    envOverlay: READ_ONLY_GIT_ENV,
    acceptExitCodes: [0, 1],
+    logger: context?.logger,
  });
  return result.exitCode === 0;
 }

-async function resolveBestComparisonBaseRef(cwd: string, baseRef: string): Promise<string> {
+async function resolveBestComparisonBaseRef(
+  cwd: string,
+  baseRef: string,
+  context?: CheckoutContext,
+): Promise<string> {
  const normalized = normalizeComparisonBaseRefName(baseRef);
  const [hasLocal, hasOrigin] = await Promise.all([
-    doesGitRefExist(cwd, `refs/heads/${normalized.localName}`),
-    doesGitRefExist(cwd, `refs/remotes/origin/${normalized.localName}`),
+    doesGitRefExist(cwd, `refs/heads/${normalized.localName}`, context),
+    doesGitRefExist(cwd, `refs/remotes/origin/${normalized.localName}`, context),
  ]);

  if (hasOrigin) {
@@ -1218,15 +1236,16 @@ async function getAheadBehind(
  cwd: string,
  baseRef: string,
  currentBranch: string,
+  context?: CheckoutContext,
 ): Promise<AheadBehind | null> {
  const normalizedBaseRef = normalizeLocalBranchRefName(baseRef);
  if (!normalizedBaseRef || !currentBranch || normalizedBaseRef === currentBranch) {
    return null;
  }
-  const comparisonBaseRef = await resolveBestComparisonBaseRef(cwd, baseRef);
+  const comparisonBaseRef = await resolveBestComparisonBaseRef(cwd, baseRef, context);
  const { stdout } = await runGitCommand(
    ["rev-list", "--left-right", "--count", `${comparisonBaseRef}...${currentBranch}`],
-    { cwd, envOverlay: READ_ONLY_GIT_ENV },
+    { cwd, envOverlay: READ_ONLY_GIT_ENV, logger: context?.logger },
  );
  const [behindRaw, aheadRaw] = stdout.trim().split(/\s+/);
  const behind = Number.parseInt(behindRaw ?? "0", 10);
@@ -1237,16 +1256,20 @@ async function getAheadBehind(
  return { ahead, behind };
 }

-async function getAheadOfOrigin(cwd: string, currentBranch: string): Promise<number | null> {
+async function getAheadOfOrigin(
+  cwd: string,
+  currentBranch: string,
+  context?: CheckoutContext,
+): Promise<number | null> {
  if (!currentBranch) {
    return null;
  }
-  const trackedOriginBranch = await getTrackedOriginBranch(cwd, currentBranch);
+  const trackedOriginBranch = await getTrackedOriginBranch(cwd, currentBranch, context);
  const originBranch = trackedOriginBranch ?? currentBranch;
  try {
    const { stdout } = await runGitCommand(
      ["rev-list", "--count", `origin/${originBranch}..${currentBranch}`],
-      { cwd, envOverlay: READ_ONLY_GIT_ENV },
+      { cwd, envOverlay: READ_ONLY_GIT_ENV, logger: context?.logger },
    );
    const count = Number.parseInt(stdout.trim(), 10);
    return Number.isNaN(count) ? null : count;
@@ -1258,6 +1281,7 @@ async function getAheadOfOrigin(cwd: string, currentBranch: string): Promise<num
      const { stdout } = await runGitCommand(["rev-list", "--count", currentBranch], {
        cwd,
        envOverlay: READ_ONLY_GIT_ENV,
+        logger: context?.logger,
      });
      const count = Number.parseInt(stdout.trim(), 10);
      return Number.isNaN(count) ? null : count;
@@ -1267,24 +1291,32 @@ async function getAheadOfOrigin(cwd: string, currentBranch: string): Promise<num
  }
 }

-async function getTrackedOriginBranch(cwd: string, currentBranch: string): Promise<string | null> {
-  const remoteName = await getGitConfigValue(cwd, `branch.${currentBranch}.remote`);
+async function getTrackedOriginBranch(
+  cwd: string,
+  currentBranch: string,
+  context?: CheckoutContext,
+): Promise<string | null> {
+  const remoteName = await getGitConfigValue(cwd, `branch.${currentBranch}.remote`, context);
  if (remoteName !== "origin") {
    return null;
  }

-  const mergeRef = await getGitConfigValue(cwd, `branch.${currentBranch}.merge`);
+  const mergeRef = await getGitConfigValue(cwd, `branch.${currentBranch}.merge`, context);
  return parseBranchMergeHeadRef(mergeRef);
 }

-async function getBehindOfOrigin(cwd: string, currentBranch: string): Promise<number | null> {
+async function getBehindOfOrigin(
+  cwd: string,
+  currentBranch: string,
+  context?: CheckoutContext,
+): Promise<number | null> {
  if (!currentBranch) {
    return null;
  }
  try {
    const { stdout } = await runGitCommand(
      ["rev-list", "--count", `${currentBranch}..origin/${currentBranch}`],
-      { cwd, envOverlay: READ_ONLY_GIT_ENV },
+      { cwd, envOverlay: READ_ONLY_GIT_ENV, logger: context?.logger },
    );
    const count = Number.parseInt(stdout.trim(), 10);
    return Number.isNaN(count) ? null : count;
@@ -1305,7 +1337,7 @@ async function inspectCheckoutContext(
  context?: CheckoutContext,
 ): Promise<CheckoutInspectionContext | null> {
  try {
-    const root = await getWorktreeRoot(cwd);
+    const root = await getWorktreeRoot(cwd, context);
    if (!root) {
      return null;
    }
@@ -1453,14 +1485,20 @@ export async function getCheckoutStatus(
  const currentBranch = inspected.currentBranch;
  const remoteUrl = inspected.remoteUrl;
  const paseoWorktree = inspected.paseoWorktree;
-  const isDirty = await isWorkingTreeDirty(cwd);
+  const isDirty = await isWorkingTreeDirty(cwd, context);
  const hasRemote = remoteUrl !== null;
  const { resolvedBaseRef: baseRef } = await resolveBaseRefForCwd(cwd, context);
  const mainRepoRoot = await getMainRepoRoot(cwd).catch(() => null);
  const [aheadBehind, aheadOfOrigin, behindOfOrigin] = await Promise.all([
-    baseRef && currentBranch ? getAheadBehind(cwd, baseRef, currentBranch) : Promise.resolve(null),
-    hasRemote && currentBranch ? getAheadOfOrigin(cwd, currentBranch) : Promise.resolve(null),
-    hasRemote && currentBranch ? getBehindOfOrigin(cwd, currentBranch) : Promise.resolve(null),
+    baseRef && currentBranch
+      ? getAheadBehind(cwd, baseRef, currentBranch, context)
+      : Promise.resolve(null),
+    hasRemote && currentBranch
+      ? getAheadOfOrigin(cwd, currentBranch, context)
+      : Promise.resolve(null),
+    hasRemote && currentBranch
+      ? getBehindOfOrigin(cwd, currentBranch, context)
+      : Promise.resolve(null),
  ]);

  if (paseoWorktree.isPaseoOwnedWorktree && baseRef) {
--- a/packages/server/src/utils/run-git-command.test.ts
+++ b/packages/server/src/utils/run-git-command.test.ts
@@ -275,6 +275,55 @@ describe("runGitCommand", () => {
    });
  });

+  it("traces git command spawn and close metadata when a logger is provided", async () => {
+    const { runGitCommand } = await loadRunGitCommand(1);
+    const trace = vi.fn();
+
+    enqueueSpawnBehaviors({ delayMs: 0, stdoutData: "ok" });
+
+    await expect(
+      runGitCommand(["status", "--short"], {
+        acceptExitCodes: [0, 1],
+        cwd: process.cwd(),
+        envOverlay: { GIT_OPTIONAL_LOCKS: "0" },
+        logger: { trace } as never,
+      }),
+    ).resolves.toMatchObject({
+      exitCode: 0,
+      stdout: "ok",
+      truncated: false,
+    });
+
+    expect(trace).toHaveBeenCalledWith(
+      expect.objectContaining({
+        command: "git",
+        args: ["status", "--short"],
+        cwd: process.cwd(),
+        cwdExists: true,
+        timeout: 30_000,
+        maxOutputBytes: 20 * 1024 * 1024,
+        acceptExitCodes: [0, 1],
+        envOverlayKeys: ["GIT_OPTIONAL_LOCKS"],
+      }),
+      "Spawning git command",
+    );
+    expect(trace).toHaveBeenCalledWith(
+      expect.objectContaining({
+        command: "git",
+        args: ["status", "--short"],
+        cwd: process.cwd(),
+        cwdExists: true,
+        durationMs: expect.any(Number),
+        exitCode: 0,
+        signal: null,
+        truncated: false,
+        stdoutBytes: 2,
+        stderrBytes: 0,
+      }),
+      "Git command closed",
+    );
+  });
+
  it("rejects non-zero exit codes that are not accepted and frees the slot", async () => {
    const { runGitCommand } = await loadRunGitCommand(1);

--- a/packages/server/src/utils/run-git-command.ts
+++ b/packages/server/src/utils/run-git-command.ts
@@ -1,4 +1,6 @@
+import { existsSync } from "node:fs";
 import pLimit from "p-limit";
+import type { Logger } from "pino";
 import type { ProcessEnvRecord } from "../server/paseo-env.js";
 import { spawnProcess } from "./spawn.js";

@@ -13,6 +15,7 @@ export interface GitCommandOptions {
  cwd: string;
  env?: ProcessEnvRecord;
  envOverlay?: ProcessEnvRecord;
+  logger?: Pick<Logger, "trace">;
  timeout?: number;
  maxOutputBytes?: number;
  acceptExitCodes?: number[];
@@ -39,6 +42,10 @@ function mergeEnvOverlays(
  return { ...env, ...envOverlay };
 }

+function getEnvOverlayKeys(envOverlay: ProcessEnvRecord | undefined): string[] {
+  return Object.keys(envOverlay ?? {}).sort();
+}
+
 export function runGitCommand(
  args: string[],
  options: GitCommandOptions,
@@ -50,10 +57,29 @@ export function runGitCommand(
        const maxOutputBytes = options.maxOutputBytes ?? DEFAULT_MAX_OUTPUT_BYTES;
        const acceptExitCodes = options.acceptExitCodes ?? [0];
        const command = formatGitCommand(args);
+        const envOverlay = mergeEnvOverlays(options.env, options.envOverlay);
+        const startedAt = Date.now();
+        const logger = typeof options.logger?.trace === "function" ? options.logger : undefined;
+        const traceContext = logger
+          ? {
+              command: "git",
+              args,
+              cwd: options.cwd,
+              cwdExists: existsSync(options.cwd),
+              timeout,
+              maxOutputBytes,
+              acceptExitCodes,
+              envOverlayKeys: getEnvOverlayKeys(envOverlay),
+            }
+          : null;
+
+        if (logger && traceContext) {
+          logger.trace(traceContext, "Spawning git command");
+        }

        const child = spawnProcess("git", args, {
          cwd: options.cwd,
-          envOverlay: mergeEnvOverlays(options.env, options.envOverlay),
+          envOverlay,
          shell: false,
          stdio: ["ignore", "pipe", "pipe"],
        });
@@ -119,6 +145,16 @@ export function runGitCommand(
        });

        child.on("error", (error) => {
+          if (logger && traceContext) {
+            logger.trace(
+              {
+                ...traceContext,
+                err: error,
+                durationMs: Date.now() - startedAt,
+              },
+              "Git command process error",
+            );
+          }
          settle(() => reject(error));
        });

@@ -130,6 +166,20 @@ export function runGitCommand(
            exitCode,
            signal,
          };
+          if (logger && traceContext) {
+            logger.trace(
+              {
+                ...traceContext,
+                durationMs: Date.now() - startedAt,
+                exitCode,
+                signal,
+                truncated,
+                stdoutBytes,
+                stderrBytes,
+              },
+              "Git command closed",
+            );
+          }

          if (!truncated && !acceptExitCodes.includes(exitCode ?? -1)) {
            const stderrPreview = result.stderr.trim() || "(no stderr)";