Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
52 changes: 52 additions & 0 deletions docs/logging_quickref.md
Original file line number Diff line number Diff line change
Expand Up @@ -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-<timestamp>/`):

```
/tmp/awf-<timestamp>/
├── 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-<ts>`, `/tmp/awf-agent-logs-<ts>`, etc.

### With `--proxy-logs-dir <path>`

When `--proxy-logs-dir` is specified (e.g., in GitHub Actions for artifact upload):

```
<proxy-logs-dir>/
├── 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 `<proxy-logs-dir>` (not a `squid-logs/` subdirectory) for historical compatibility with GitHub Actions workflows that glob `<proxy-logs-dir>/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.
25 changes: 20 additions & 5 deletions src/topology.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ jest.mock('./docker-host', () => ({
}));
jest.mock('./logger', () => ({
logger: {
debug: jest.fn(),
info: jest.fn(),
warn: jest.fn(),
error: jest.fn(),
Expand Down Expand Up @@ -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();
Expand All @@ -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();
Expand Down
41 changes: 27 additions & 14 deletions src/topology.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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<boolean> {
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;
}

/**
Expand Down
75 changes: 75 additions & 0 deletions src/workdir-setup.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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', () => {
Expand Down
60 changes: 53 additions & 7 deletions src/workdir-setup.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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).
Comment thread
Copilot marked this conversation as resolved.
// 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 */ }
}
},
});
Expand Down Expand Up @@ -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
}
}

/**
Expand Down Expand Up @@ -321,4 +365,6 @@ export const workdirSetupTestHelpers = {
prepareLogDirectories,
prepareChrootHomeMounts,
ensureInitSignalDir,
pruneStaleMcpLogDirs,
MCP_LOGS_MAX_AGE_MS,
};
Loading