From 912eea4f7fb74f2e2650d8d98fe33ced54734f75 Mon Sep 17 00:00:00 2001 From: Konstantin Wohlwend Date: Fri, 26 Jun 2026 14:08:03 -0700 Subject: [PATCH] Improve local agent update logging --- .../remote-development-environment/manager.ts | 136 ++++++++++++++++-- packages/shared-backend/src/index.ts | 97 ++++++++++++- 2 files changed, 218 insertions(+), 15 deletions(-) diff --git a/apps/dashboard/src/lib/remote-development-environment/manager.ts b/apps/dashboard/src/lib/remote-development-environment/manager.ts index 9be7e0da8..f3605901f 100644 --- a/apps/dashboard/src/lib/remote-development-environment/manager.ts +++ b/apps/dashboard/src/lib/remote-development-environment/manager.ts @@ -36,6 +36,7 @@ const CONFIG_SYNC_FORMAT_VERSION = 2; const LOG_PREFIX = "[Stack RDE]"; const RDE_DASHBOARD_LOG_PATH_ENV_VAR = "HEXCLAVE_RDE_DASHBOARD_LOG_PATH"; const CONFIG_SYNC_DUPLICATE_EVENT_SUPPRESSION_MS = 2_000; +const CONFIG_UPDATE_LOG_PATH_LIMIT = 40; export class RemoteDevelopmentEnvironmentApiUnavailableError extends Error { constructor(apiBaseUrl: string, cause: unknown) { @@ -205,6 +206,45 @@ function warnRemoteDevelopmentEnvironment(message: string, details?: Record { + if (error instanceof Error) { + const cause = Reflect.get(error, "cause"); + return { + errorName: error.name, + errorMessage: error.message, + errorStack: error.stack, + ...(cause == null ? {} : { errorCause: errorToNiceString(cause) }), + }; + } + return { + errorMessage: errorToNiceString(error), + }; +} + +function collectConfigUpdatePaths(config: Config, prefix: string, paths: string[]): void { + for (const [key, value] of Object.entries(config)) { + if (value === undefined) continue; + const path = prefix.length === 0 ? key : `${prefix}.${key}`; + if (value != null && typeof value === "object" && !Array.isArray(value)) { + collectConfigUpdatePaths(value, path, paths); + } else { + paths.push(path); + } + } +} + +function summarizeConfigUpdateForLog(configUpdate: Config): Record { + const configUpdatePaths: string[] = []; + collectConfigUpdatePaths(configUpdate, "", configUpdatePaths); + configUpdatePaths.sort(); + return { + configUpdateTopLevelKeys: Object.keys(configUpdate).sort(), + configUpdatePathCount: configUpdatePaths.length, + configUpdatePaths: configUpdatePaths.slice(0, CONFIG_UPDATE_LOG_PATH_LIMIT), + configUpdatePathsTruncated: configUpdatePaths.length > CONFIG_UPDATE_LOG_PATH_LIMIT, + }; +} + function configSyncEventsMatchForCliDeduplication(a: ConfigSyncEvent, b: { status: "success" } | { status: "error", errorMessage: string }): boolean { if (a.status !== b.status) { return false; @@ -315,6 +355,7 @@ function getStackAppRequestInternals(appValue: unknown): HexclaveAppRequestInter function beginRemoteDevelopmentEnvironmentOperation(name: string, details?: Record): () => void { const state = getGlobals(); + const startedAtMs = performance.now(); state.activeOperations += 1; logRemoteDevelopmentEnvironment(`Started ${name}`, { ...details, @@ -329,6 +370,7 @@ function beginRemoteDevelopmentEnvironmentOperation(name: string, details?: Reco logRemoteDevelopmentEnvironment(`Finished ${name}`, { ...details, activeOperations: state.activeOperations, + elapsedMs: Math.round(performance.now() - startedAtMs), }); }; } @@ -1069,63 +1111,125 @@ export async function applyRemoteDevelopmentEnvironmentConfigUpdate(options: { waitForSync?: boolean, }): Promise { assertRemoteDevelopmentEnvironmentEnabled(); - const endOperation = beginRemoteDevelopmentEnvironmentOperation("config update", { + const configUpdateOperationId = randomUUID(); + const waitForSync = options.waitForSync ?? true; + const configUpdateLogDetails = { + configUpdateOperationId, sessionId: options.sessionId, projectId: options.projectId, + waitForSync, + ...summarizeConfigUpdateForLog(options.configUpdate), + }; + const endOperation = beginRemoteDevelopmentEnvironmentOperation("config update", { + ...configUpdateLogDetails, }); + let resolvedConfigFilePath: string | undefined; try { const state = getGlobals(); - const session = (() => { + const sessionEntry = (() => { if (options.sessionId != null) { - return state.sessions.get(options.sessionId); + const session = state.sessions.get(options.sessionId); + return session == null ? undefined : { sessionId: options.sessionId, session }; } if (options.projectId == null) { throw new Error("Remote development environment config update requires a session ID or project ID."); } - for (const activeSession of state.sessions.values()) { + for (const [sessionId, activeSession] of state.sessions.entries()) { const stateProject = readRemoteDevelopmentEnvironmentState().projectsByConfigPath[activeSession.configFilePath]; if (stateProject?.projectId === options.projectId) { - return activeSession; + return { sessionId, session: activeSession }; } } return undefined; })(); - if (session == null) { + if (sessionEntry == null) { + warnRemoteDevelopmentEnvironment("Could not resolve active session for config update", { + ...configUpdateLogDetails, + activeSessions: state.sessions.size, + }); throw new Error("Remote development environment session is not active."); } + const session = sessionEntry.session; const configFilePath = session.configFilePath; + resolvedConfigFilePath = configFilePath; + logRemoteDevelopmentEnvironment("Resolved active session for config update", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + activeSessions: state.sessions.size, + }); logRemoteDevelopmentEnvironment("Applying config update from local dashboard", { - sessionId: options.sessionId, - projectId: options.projectId, + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, configFilePath, }); - if (options.waitForSync === false) { + const localWriteStartedAtMs = performance.now(); + if (!waitForSync) { + logRemoteDevelopmentEnvironment("Writing config update without waiting for remote sync", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + }); const currentConfig = (await readConfigFile(configFilePath)).config; await replaceConfigObject(configFilePath, override(currentConfig, options.configUpdate)); scheduleSync(configFilePath); + logRemoteDevelopmentEnvironment("Wrote config update and scheduled remote sync", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + localWriteElapsedMs: Math.round(performance.now() - localWriteStartedAtMs), + }); } else { state.synchronouslyUpdatingConfigFiles.add(configFilePath); try { + logRemoteDevelopmentEnvironment("Writing config update before immediate remote sync", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + }); await updateConfigObject(configFilePath, options.configUpdate); + logRemoteDevelopmentEnvironment("Wrote config update before immediate remote sync", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + localWriteElapsedMs: Math.round(performance.now() - localWriteStartedAtMs), + }); } finally { setTimeout(() => { state.synchronouslyUpdatingConfigFiles.delete(configFilePath); }, SYNC_DEBOUNCE_MS).unref(); } try { + const syncStartedAtMs = performance.now(); const result = await syncConfigToRemoteNow(configFilePath); if (result.pushedConfig) { recordConfigSyncEvent(configFilePath, { status: "success" }); } + logRemoteDevelopmentEnvironment("Immediate remote sync after config update completed", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + syncElapsedMs: Math.round(performance.now() - syncStartedAtMs), + pushedConfig: result.pushedConfig, + onboardingStatus: result.onboardingStatus, + }); } catch (error) { const errorMessage = errorToNiceString(error); + warnRemoteDevelopmentEnvironment("Immediate remote sync after config update failed", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, + configFilePath, + ...formatErrorForRemoteDevelopmentEnvironmentLog(error), + }); state.syncErrors.set(configFilePath, error instanceof Error ? error : new Error(errorMessage)); const cliErrorMessage = formatConfigSyncErrorForCli(configFilePath, error); await updateRemoteDevelopmentEnvironmentPushedConfigError(configFilePath, cliErrorMessage) .catch((pushedConfigErrorUpdateError: unknown) => { warnRemoteDevelopmentEnvironment("Failed to update pushed config error after dashboard config sync failure", { + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, configFilePath, - error: errorToNiceString(pushedConfigErrorUpdateError), + ...formatErrorForRemoteDevelopmentEnvironmentLog(pushedConfigErrorUpdateError), }); }); recordConfigSyncEvent(configFilePath, { @@ -1136,11 +1240,17 @@ export async function applyRemoteDevelopmentEnvironmentConfigUpdate(options: { } } logRemoteDevelopmentEnvironment("Applied config update from local dashboard", { - sessionId: options.sessionId, - projectId: options.projectId, + ...configUpdateLogDetails, + resolvedSessionId: sessionEntry.sessionId, configFilePath, - waitForSync: options.waitForSync ?? true, }); + } catch (error) { + warnRemoteDevelopmentEnvironment("Failed to apply config update from local dashboard", { + ...configUpdateLogDetails, + ...(resolvedConfigFilePath == null ? {} : { configFilePath: resolvedConfigFilePath }), + ...formatErrorForRemoteDevelopmentEnvironmentLog(error), + }); + throw error; } finally { endOperation(); } diff --git a/packages/shared-backend/src/index.ts b/packages/shared-backend/src/index.ts index 9ea34211c..4437ee9dd 100644 --- a/packages/shared-backend/src/index.ts +++ b/packages/shared-backend/src/index.ts @@ -13,6 +13,7 @@ const jiti = createJiti(import.meta.url, { moduleCache: false }); const LOG_PREFIX = "[Stack config updater]"; const DEFAULT_AGENT_TIMEOUT_MS = 120_000; +const CONFIG_UPDATE_LOG_PATH_LIMIT = 40; type ConfigModule = { config?: unknown, @@ -21,6 +22,28 @@ type ConfigModule = { type ConfigFileSnapshot = { path: string, content: string | null }; type ConfigChange = { path: string, value: ConfigValue }; +function formatConfigUpdaterErrorForLog(error: unknown): Record { + if (error instanceof Error) { + return { + errorName: error.name, + errorMessage: error.message, + errorStack: error.stack, + }; + } + return { + errorMessage: String(error), + }; +} + +function configUpdatePathDetailsForLog(changes: ConfigChange[]): Record { + const paths = changes.map(({ path: configPath }) => configPath).sort(); + return { + configUpdatePathCount: paths.length, + configUpdatePaths: paths.slice(0, CONFIG_UPDATE_LOG_PATH_LIMIT), + configUpdatePathsTruncated: paths.length > CONFIG_UPDATE_LOG_PATH_LIMIT, + }; +} + function isConfigModule(value: unknown): value is ConfigModule { return value !== null && typeof value === "object"; } @@ -124,9 +147,21 @@ function renderConfigObjectToFile(configFilePath: string, config: Config): void } export async function updateConfigObject(configFilePath: string, configUpdate: Config): Promise { + const startedAtMs = performance.now(); ensureConfigFileExists(configFilePath); - if (flattenConfigUpdate(configUpdate).length === 0) return; + const changes = flattenConfigUpdate(configUpdate); + if (changes.length === 0) { + console.log(`${LOG_PREFIX} Skipping config update because it contains no changes`, { + configFilePath, + }); + return; + } + const updateLogDetails = { + configFilePath, + ...configUpdatePathDetailsForLog(changes), + }; + console.log(`${LOG_PREFIX} Starting config file update`, updateLogDetails); const content = readFileSync(configFilePath, "utf-8"); @@ -134,16 +169,25 @@ export async function updateConfigObject(configFilePath: string, configUpdate: C // apply the update deterministically without invoking the AI agent. const staticConfig = tryParseStaticConfigFileContent(content, configFilePath); if (staticConfig != null && isValidConfig(staticConfig)) { + console.log(`${LOG_PREFIX} Applying config update with static config rewrite`, updateLogDetails); const merged = override(staticConfig, configUpdate); if (!isValidConfig(merged)) { throw new Error(`${LOG_PREFIX} Merged config is invalid after applying update to ${configFilePath}`); } renderConfigObjectToFile(configFilePath, merged); + console.log(`${LOG_PREFIX} Finished config update with static config rewrite`, { + ...updateLogDetails, + elapsedMs: Math.round(performance.now() - startedAtMs), + }); return; } // Agent path: config has custom structure (imports, helpers, external files) // that must be preserved — delegate to the AI agent. + console.log(`${LOG_PREFIX} Applying config update with agent-assisted rewrite`, { + ...updateLogDetails, + configDirectory: path.dirname(configFilePath), + }); const baselineConfig = await tryReadConfigForValidation(configFilePath); const { snapshots, seen } = snapshotConfigFiles(configFilePath, content); try { @@ -154,16 +198,31 @@ export async function updateConfigObject(configFilePath: string, configUpdate: C }); await validateAgentUpdate(configFilePath, baselineConfig, configUpdate, snapshots); } catch (error) { + console.warn(`${LOG_PREFIX} Config update failed; restoring files from snapshots`, { + ...updateLogDetails, + snapshotCount: snapshots.length, + elapsedMs: Math.round(performance.now() - startedAtMs), + ...formatConfigUpdaterErrorForLog(error), + }); try { restoreConfigFiles(snapshots); + console.warn(`${LOG_PREFIX} Restored files after failed config update`, { + ...updateLogDetails, + snapshotCount: snapshots.length, + }); } catch (restoreError) { console.error(`${LOG_PREFIX} Failed to fully roll back config files after a failed update of ${configFilePath}; some files may be left in a partially-restored state`, { configFilePath, - restoreError: restoreError instanceof Error ? restoreError.message : String(restoreError), + ...formatConfigUpdaterErrorForLog(restoreError), }); } throw error; } + console.log(`${LOG_PREFIX} Finished config update with agent-assisted rewrite`, { + ...updateLogDetails, + elapsedMs: Math.round(performance.now() - startedAtMs), + snapshotCount: snapshots.length, + }); } export async function replaceConfigObject(configFilePath: string, config: Config): Promise { @@ -177,6 +236,11 @@ async function runConfigUpdateAgent(options: { }): Promise { const timeoutMs = parseAgentTimeoutMs(); const deniedOutOfBoundsWrites = new Set(); + const startedAtMs = performance.now(); + console.log(`${LOG_PREFIX} Starting config update agent`, { + cwd: options.cwd, + timeoutMs, + }); try { await runHeadlessClaudeAgent({ prompt: options.prompt, @@ -204,14 +268,43 @@ async function runConfigUpdateAgent(options: { }); } catch (error) { if (error instanceof ClaudeAgentTimeoutError) { + console.warn(`${LOG_PREFIX} Config update agent timed out`, { + cwd: options.cwd, + timeoutMs, + elapsedMs: Math.round(performance.now() - startedAtMs), + ...formatConfigUpdaterErrorForLog(error), + }); throw new Error(`Config update agent timed out after ${timeoutMs}ms. It was unable to apply the config changes to the file.`); } if (error instanceof ClaudeAgentFailureError) { + console.warn(`${LOG_PREFIX} Config update agent failed`, { + cwd: options.cwd, + timeoutMs, + elapsedMs: Math.round(performance.now() - startedAtMs), + ...formatConfigUpdaterErrorForLog(error), + }); throw new Error(`${error.message} It was unable to apply the config changes to the file.`); } + console.warn(`${LOG_PREFIX} Config update agent failed unexpectedly`, { + cwd: options.cwd, + timeoutMs, + elapsedMs: Math.round(performance.now() - startedAtMs), + ...formatConfigUpdaterErrorForLog(error), + }); throw error; } + console.log(`${LOG_PREFIX} Finished config update agent`, { + cwd: options.cwd, + timeoutMs, + elapsedMs: Math.round(performance.now() - startedAtMs), + deniedOutOfBoundsWriteCount: deniedOutOfBoundsWrites.size, + }); if (deniedOutOfBoundsWrites.size > 0) { + console.warn(`${LOG_PREFIX} Config update agent attempted out-of-bounds writes`, { + cwd: options.cwd, + deniedOutOfBoundsWriteCount: deniedOutOfBoundsWrites.size, + deniedOutOfBoundsWrites: [...deniedOutOfBoundsWrites], + }); throw new Error(`Config update agent tried to modify ${deniedOutOfBoundsWrites.size} file(s) outside the config directory, which is not allowed: ${[...deniedOutOfBoundsWrites].join(", ")}. The config was not updated.`); } }