diff --git a/docs/logging_quickref.md b/docs/logging_quickref.md index 9275e5038..bd7052c07 100644 --- a/docs/logging_quickref.md +++ b/docs/logging_quickref.md @@ -376,3 +376,55 @@ docker exec awf-squid awk 'NF != 10' /var/log/squid/access.log - [Squid Log Filtering](squid_log_filtering.md) - Filtering Squid access logs - [Troubleshooting](troubleshooting.md) - Common issues and fixes - [README.md](../README.md) - Main project documentation + +## Log Directory Layout + +### Default (no `--proxy-logs-dir`) + +All logs are written under the temporary work directory (`/tmp/awf-/`): + +``` +/tmp/awf-/ +├── squid-logs/ # Squid access.log (owned by UID 13:13) +├── agent-logs/ # Copilot CLI logs (owned by host UID:GID) +├── agent-session-state/ # Session events.jsonl (owned by host UID:GID) +├── api-proxy-logs/ # API proxy sidecar logs (mode 0777) +└── cli-proxy-logs/ # CLI proxy logs (mode 0777) +``` + +After cleanup, non-empty dirs are preserved to `/tmp/squid-logs-`, `/tmp/awf-agent-logs-`, etc. + +### With `--proxy-logs-dir ` + +When `--proxy-logs-dir` is specified (e.g., in GitHub Actions for artifact upload): + +``` +/ +├── access.log # Squid writes DIRECTLY here (no subdirectory) +├── api-proxy-logs/ # API proxy logs in subdirectory +└── cli-proxy-logs/ # CLI proxy logs in subdirectory +``` + +**Note:** Squid logs write directly to `` (not a `squid-logs/` subdirectory) for historical compatibility with GitHub Actions workflows that glob `/access.log`. The api-proxy and cli-proxy logs use subdirectories to avoid filename collisions. + +### MCP Gateway Logs + +MCP gateway logs are written to a fixed host path: + +``` +/tmp/gh-aw/mcp-logs/ # Host-visible, not inside workDir +``` + +This directory is pruned of subdirectories older than 24 hours on each AWF invocation. + +### Ownership & Permissions (ARC/DinD) + +On ARC/DinD runners with split filesystems, the Docker daemon may auto-create +bind-mount source directories as `root:root`, overriding host-side ownership. +AWF uses a triple-layer defense to ensure correct permissions: + +1. **Host-side prep** (`workdir-setup.ts`): best-effort `chown` to service UID during workdir setup (runs even if the directory already exists) +2. **Container preflight** (`squid-service.ts`): `chown`/`chmod` inside the container before the service starts +3. **Pre-shutdown repair** (`container-stop.ts`): `chmod -R a+rX` while container is still running + +Each layer compensates for the others' failure modes across different topologies. diff --git a/src/topology.test.ts b/src/topology.test.ts index 5ded96dc7..3283b9c99 100644 --- a/src/topology.test.ts +++ b/src/topology.test.ts @@ -11,6 +11,7 @@ jest.mock('./docker-host', () => ({ })); jest.mock('./logger', () => ({ logger: { + debug: jest.fn(), info: jest.fn(), warn: jest.fn(), error: jest.fn(), @@ -47,18 +48,32 @@ describe('topology', () => { exitSpy.mockRestore(); }); - it('exits when the Docker daemon is unreachable', async () => { - mockedExeca.mockResolvedValueOnce({ exitCode: 1 } as any); + it('returns without exiting when daemon becomes reachable on retry', async () => { + mockedExeca + .mockResolvedValueOnce({ exitCode: 1 } as any) // attempt 1 fails + .mockResolvedValueOnce({ exitCode: 0 } as any); // attempt 2 succeeds + const exitSpy = jest.spyOn(process, 'exit').mockImplementation((() => undefined) as never); + + await assertTopologySupported(); + + expect(exitSpy).not.toHaveBeenCalled(); + expect(mockedExeca).toHaveBeenCalledTimes(2); + exitSpy.mockRestore(); + }); + + it('exits when the Docker daemon is unreachable after all retries', async () => { + mockedExeca.mockResolvedValue({ exitCode: 1 } as any); const exitSpy = jest.spyOn(process, 'exit').mockImplementation((() => undefined) as never); await assertTopologySupported(); expect(exitSpy).toHaveBeenCalledWith(1); + expect(mockedExeca).toHaveBeenCalledTimes(3); // all retries exhausted exitSpy.mockRestore(); }); - it('exits when the Docker daemon probe throws', async () => { - mockedExeca.mockRejectedValueOnce(new Error('spawn docker ENOENT')); + it('exits when the Docker daemon probe throws on all retries', async () => { + mockedExeca.mockRejectedValue(new Error('spawn docker ENOENT')); const exitSpy = jest.spyOn(process, 'exit').mockImplementation((() => undefined) as never); await assertTopologySupported(); @@ -69,7 +84,7 @@ describe('topology', () => { it('exits when an ARC kubernetes-native runner is detected', async () => { process.env.ACTIONS_RUNNER_CONTAINER_HOOKS = '/hooks/index.js'; - mockedExeca.mockResolvedValueOnce({ exitCode: 1 } as any); + mockedExeca.mockResolvedValue({ exitCode: 1 } as any); const exitSpy = jest.spyOn(process, 'exit').mockImplementation((() => undefined) as never); await assertTopologySupported(); diff --git a/src/topology.ts b/src/topology.ts index c6265573e..de3281a8e 100644 --- a/src/topology.ts +++ b/src/topology.ts @@ -11,6 +11,8 @@ import { logger } from './logger'; export const TOPOLOGY_NETWORK_NAME = 'awf-net'; const DAEMON_PING_TIMEOUT_MS = 5000; +const DAEMON_PING_RETRIES = 3; +const DAEMON_PING_RETRY_DELAY_MS = 2000; interface TopologyLogger { info: (message: string, ...args: unknown[]) => void; @@ -19,23 +21,34 @@ interface TopologyLogger { /** * Returns true if the Docker daemon is reachable via `docker info`. - * Uses a short timeout so the fail-stop preflight does not hang. + * Retries with backoff to tolerate transient daemon unresponsiveness + * (e.g., when the daemon is under load from concurrent container healthchecks + * and image operations during GitHub Actions job startup). */ async function isDockerDaemonReachable(): Promise { - try { - const result = await execa( - 'docker', - ['info', '--format', '{{.ServerVersion}}'], - { - env: getLocalDockerEnv(), - timeout: DAEMON_PING_TIMEOUT_MS, - reject: false, - }, - ); - return result.exitCode === 0; - } catch { - return false; + for (let attempt = 1; attempt <= DAEMON_PING_RETRIES; attempt++) { + try { + const result = await execa( + 'docker', + ['info', '--format', '{{.ServerVersion}}'], + { + env: getLocalDockerEnv(), + timeout: DAEMON_PING_TIMEOUT_MS, + reject: false, + }, + ); + if (result.exitCode === 0) { + return true; + } + } catch { + // timeout or exec failure — retry + } + if (attempt < DAEMON_PING_RETRIES) { + logger.debug(`Docker daemon probe attempt ${attempt}/${DAEMON_PING_RETRIES} failed, retrying in ${DAEMON_PING_RETRY_DELAY_MS}ms...`); + await new Promise(resolve => setTimeout(resolve, DAEMON_PING_RETRY_DELAY_MS)); + } } + return false; } /** diff --git a/src/workdir-setup.test.ts b/src/workdir-setup.test.ts index ddd2dd057..215c2b8fd 100644 --- a/src/workdir-setup.test.ts +++ b/src/workdir-setup.test.ts @@ -212,6 +212,81 @@ describe('prepareWorkDirectories', () => { const mode = fs.statSync(proxyLogsDir).mode & 0o777; expect(mode).toBe(0o777); }); + + it('repairs squid logs ownership even when directory pre-exists', () => { + const config = buildConfig(); + const logPaths = resolveLogPaths(config); + + // Pre-create the squid logs directory (simulates leftover from crashed run) + fs.mkdirSync(logPaths.squidLogs, { recursive: true }); + + prepareWorkDirectories(config, logPaths); + + // chown should still be called (onAfterEnsure, not just onCreate) + expect(fs.chownSync).toHaveBeenCalledWith(logPaths.squidLogs, 13, 13); + }); + + it('tolerates both chown and chmod failure on squid logs (best-effort)', () => { + const config = buildConfig(); + const logPaths = resolveLogPaths(config); + + (fs.chownSync as unknown as jest.Mock).mockImplementation((targetPath: fs.PathLike) => { + if (String(targetPath) === logPaths.squidLogs) { + throw new Error('chown failed'); + } + }); + (fs.chmodSync as jest.Mock).mockImplementation((targetPath: fs.PathLike) => { + if (String(targetPath) === logPaths.squidLogs) { + throw new Error('chmod failed'); + } + actualFs.chmodSync(targetPath as string, 0o777); + }); + + // Should not throw — container entrypoint preflight will handle it + expect(() => prepareWorkDirectories(config, logPaths)).not.toThrow(); + }); + }); + + describe('MCP log pruning', () => { + it('removes subdirectories older than 24 hours', () => { + const mcpLogsDir = path.join(fixture.tempDir, 'mcp-logs'); + fs.mkdirSync(mcpLogsDir, { recursive: true }); + + // Create a "stale" subdir and set its mtime to 25 hours ago + const staleDir = path.join(mcpLogsDir, 'stale-session'); + fs.mkdirSync(staleDir); + const oldTime = new Date(Date.now() - 25 * 60 * 60 * 1000); + fs.utimesSync(staleDir, oldTime, oldTime); + + // Create a "fresh" subdir (mtime is now) + const freshDir = path.join(mcpLogsDir, 'fresh-session'); + fs.mkdirSync(freshDir); + + workdirSetupTestHelpers.pruneStaleMcpLogDirs(mcpLogsDir); + + expect(fs.existsSync(staleDir)).toBe(false); + expect(fs.existsSync(freshDir)).toBe(true); + }); + + it('skips files (only prunes directories)', () => { + const mcpLogsDir = path.join(fixture.tempDir, 'mcp-logs'); + fs.mkdirSync(mcpLogsDir, { recursive: true }); + + const staleFile = path.join(mcpLogsDir, 'old-file.log'); + fs.writeFileSync(staleFile, 'data'); + const oldTime = new Date(Date.now() - 25 * 60 * 60 * 1000); + fs.utimesSync(staleFile, oldTime, oldTime); + + workdirSetupTestHelpers.pruneStaleMcpLogDirs(mcpLogsDir); + + expect(fs.existsSync(staleFile)).toBe(true); + }); + + it('tolerates unreadable directory without throwing', () => { + expect(() => { + workdirSetupTestHelpers.pruneStaleMcpLogDirs('/nonexistent/path'); + }).not.toThrow(); + }); }); describe('chroot home bind-mount preparation', () => { diff --git a/src/workdir-setup.ts b/src/workdir-setup.ts index 836142cd7..b7066a8a7 100644 --- a/src/workdir-setup.ts +++ b/src/workdir-setup.ts @@ -142,20 +142,34 @@ function prepareLogDirectories(logPaths: LogPaths): void { // Create squid logs directory for persistence // If proxyLogsDir is specified, write directly there (timeout-safe) // Otherwise, use workDir/squid-logs (will be moved to /tmp after cleanup) - // Note: Squid runs as user 'proxy' (UID 13, GID 13 in ubuntu/squid image) - // We need to make the directory writable by the proxy user - // Squid container runs as non-root 'proxy' user (UID 13, GID 13) - // Set ownership so proxy user can write logs without root privileges + // + // TRIPLE-LAYER DEFENSE for squid log permissions: + // Layer 1 (here): best-effort chown to UID 13:13 on the host filesystem during workdir setup. + // On non-ARC deployments this is typically sufficient. + // On ARC/DinD this may be a no-op (daemon has a different filesystem view). + // Layer 2 (squid-service.ts entrypoint): chown preflight inside the container. + // Repairs ownership when Docker daemon auto-creates the bind-mount source + // as root:root on split filesystems. Required for ARC/DinD. + // Layer 3 (container-stop.ts): chmod -R a+rX before compose down. + // Ensures the runner user can read log files (owned by UID 13) after + // the container is removed, for `awf logs summary` and artifact uploads. + // + // Each layer compensates for the others' failure modes. Do not remove any + // layer without understanding all deployment topologies (shared FS, DinD, + // rootless Docker, NFS root-squash). const SQUID_PROXY_UID = 13; const SQUID_PROXY_GID = 13; ensureDirectory(logPaths.squidLogs, { mode: 0o755, - onCreate: () => { + onAfterEnsure: () => { try { fs.chownSync(logPaths.squidLogs, SQUID_PROXY_UID, SQUID_PROXY_GID); } catch { - // Fallback to world-writable if chown fails (e.g., non-root context) - fs.chmodSync(logPaths.squidLogs, 0o777); + // Fallback to world-writable if chown fails (e.g., non-root context, + // pre-existing dir owned by another user, NFS root-squash) + try { + fs.chmodSync(logPaths.squidLogs, 0o777); + } catch { /* best-effort — container entrypoint preflight will retry */ } } }, }); @@ -207,6 +221,36 @@ function prepareLogDirectories(logPaths: LogPaths): void { logger.debug(`MCP logs directory already exists at: ${mcpLogsDir} (chmod skipped: ${code})`); } } + + // Prune stale MCP log subdirectories to prevent unbounded growth on persistent + // runners. Each AWF run or MCP gateway session creates timestamped subdirs; + // without pruning these accumulate indefinitely since mcpLogsDir lives outside + // workDir and is not cleaned up by removeWorkDirectories(). + pruneStaleMcpLogDirs(mcpLogsDir); +} + +const MCP_LOGS_MAX_AGE_MS = 24 * 60 * 60 * 1000; // 24 hours + +function pruneStaleMcpLogDirs(mcpLogsDir: string): void { + try { + const entries = fs.readdirSync(mcpLogsDir, { withFileTypes: true }); + const now = Date.now(); + for (const entry of entries) { + if (!entry.isDirectory()) continue; + const dirPath = path.join(mcpLogsDir, entry.name); + try { + const stat = fs.statSync(dirPath); + if (now - stat.mtimeMs > MCP_LOGS_MAX_AGE_MS) { + fs.rmSync(dirPath, { recursive: true, force: true }); + logger.debug(`Pruned stale MCP log directory: ${dirPath}`); + } + } catch { + // Skip entries we can't stat or remove (owned by another user, etc.) + } + } + } catch { + // Best-effort: if we can't read the directory, skip pruning silently + } } /** @@ -321,4 +365,6 @@ export const workdirSetupTestHelpers = { prepareLogDirectories, prepareChrootHomeMounts, ensureInitSignalDir, + pruneStaleMcpLogDirs, + MCP_LOGS_MAX_AGE_MS, };