diff --git a/packages/server/src/server/workspace-git-service.ts b/packages/server/src/server/workspace-git-service.ts index 9651b6543..739ed1a32 100644 --- 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(); diff --git a/packages/server/src/utils/checkout-git.ts b/packages/server/src/utils/checkout-git.ts index 8a1ca0f1c..e242abe6d 100644 --- 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; } function isGitError(error: unknown): boolean { @@ -767,11 +769,12 @@ async function getRebaseHeadBranch(cwd: string): Promise { return results.find((result): result is string => result !== null) ?? null; } -async function getWorktreeRoot(cwd: string): Promise { +async function getWorktreeRoot(cwd: string, context?: CheckoutContext): Promise { 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 { +async function isWorkingTreeDirty(cwd: string, context?: CheckoutContext): Promise { 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 { return url !== null; } -async function getGitConfigValue(cwd: string, key: string): Promise { +async function getGitConfigValue( + cwd: string, + key: string, + context?: CheckoutContext, +): Promise { 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 { +async function doesGitRefExist( + cwd: string, + fullRef: string, + context?: CheckoutContext, +): Promise { 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 { +async function resolveBestComparisonBaseRef( + cwd: string, + baseRef: string, + context?: CheckoutContext, +): Promise { 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 { 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 { +async function getAheadOfOrigin( + cwd: string, + currentBranch: string, + context?: CheckoutContext, +): Promise { 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 { - const remoteName = await getGitConfigValue(cwd, `branch.${currentBranch}.remote`); +async function getTrackedOriginBranch( + cwd: string, + currentBranch: string, + context?: CheckoutContext, +): Promise { + 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 { +async function getBehindOfOrigin( + cwd: string, + currentBranch: string, + context?: CheckoutContext, +): Promise { 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 { 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) { diff --git a/packages/server/src/utils/run-git-command.test.ts b/packages/server/src/utils/run-git-command.test.ts index 022e75dfb..371b0d335 100644 --- 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); diff --git a/packages/server/src/utils/run-git-command.ts b/packages/server/src/utils/run-git-command.ts index 8e1fc59c3..2ff2dd14c 100644 --- 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; 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)";