Skip to content

Commit c693e63

Browse files
committed
feat(daemon): log startup, socket, driver, and connection lifecycle
daemon.log has been an empty crash dump since the daemon's only write to either stream was a fatal console.error(). There was no startup line, no shutdown line, and no record of socket claim/recovery or driver discovery, so a misbehaving long-lived daemon left no trace to read back. Adds a Logger port (JsonLinesLogger over an injected LogSink, with module-scoped child()) alongside the existing Filesystem/Clock/DaemonLauncher ports. Production logging goes through NodeFileLogSink, which owns an append handle on ~/.pitlane/daemon.log, tracks bytes written, and rotates to daemon.log.1 (replacing any previous generation) once config.log.rotateBytes is exceeded -- keeping exactly one rotated generation so growth is bounded. Tests use MemoryLogSink and assert parsed records, not string fragments. startDaemon builds the logger from config.log.level right after config loads and hands scoped children to DaemonEndpointHost, DaemonServer, and driver discovery, covering: daemon start (version, protocol version, socket path, effective config), socket claim and stale-endpoint recovery, driver discovery results including the Android SDK-missing skip, connection open/close with declared capabilities, clean shutdown, and unexpected vs. handled request errors (INTERNAL logs at error level, everything else at debug). The fatal top-level handler in main.ts can't depend on config.log -- config loading is exactly what may have failed -- so it builds its own logger straight from the default log path at a fixed level, falling back to console.error only if that itself throws. Because NodeDaemonLauncher hands the child an inherited append fd on the same path for uncaught fatal output, a crash stack can still land in the rotated file. pitlane daemon logs now reads daemon.log.1 followed by daemon.log so a crash right before rotation is never silently lost. Config gained a log section (level, default "info"; rotateBytes, default 5 MiB), validated like its neighbors and readable via `pitlane config get log`.
1 parent b469e73 commit c693e63

26 files changed

Lines changed: 905 additions & 9 deletions

‎docs/ARCHITECTURE.md‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -252,6 +252,7 @@ Clock — now(), timers (no direct Date/setTimeout in logic)
252252
SystemStats — cpu count, total/free RAM, disk free
253253
IpcConnector / IpcListenerFactory — connect to and host daemon IPC endpoints
254254
DaemonLauncher — detached daemon startup with append-only combined logs
255+
Logger — debug/info/warn/error(message, fields) plus child(module) scoping
255256
```
256257

257258
Real implementations are thin adapters wired up once at daemon startup;
@@ -275,6 +276,23 @@ request multiplexing, `IpcDaemonConnector` performs the hello handshake, and
275276
or refused daemon. This keeps transport, detached-process logging, and startup
276277
policies replaceable without introducing an ambient dependency container.
277278

279+
Operational logging is a separate concern from the event bus: `pitlane events`
280+
carries business facts (lease granted, device cleaned up, …) in an in-memory
281+
ring buffer that resets on restart, while the `Logger` port writes durable,
282+
structured JSON lines — one per record — for startup, socket claim/recovery,
283+
driver discovery, connection lifecycle, shutdown, and unexpected/handled
284+
errors. `startDaemon` builds the production `Logger` (`JsonLinesLogger` over a
285+
`NodeFileLogSink`) from `config.log` right after config loads, then hands
286+
module-scoped children (`logger.child("server")`, `.child("connection-host")`,
287+
`.child("driver-discovery")`) to each component so every line is attributable.
288+
The sink tracks bytes written and rotates `daemon.log` to `daemon.log.1`
289+
(replacing any previous generation) once `config.log.rotateBytes` is exceeded,
290+
so growth is bounded and `pitlane daemon logs` reads the rotated generation
291+
before the current file. The one exception is the fatal top-level handler: it
292+
cannot depend on `config.log` having loaded successfully, so it builds its own
293+
logger straight from the default log path at a fixed level, falling back to
294+
`console.error` only if that itself fails.
295+
278296
## Device requests
279297

280298
Required to identify a device: **platform + device model + OS version**.

‎docs/CLI.md‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -214,10 +214,19 @@ lines. `--follow` keeps streaming; `--since 1h` replays recent history.
214214
Manage the daemon explicitly. Other commands auto-start it on demand;
215215
`daemon` exists for operators and debugging. `logs` tails daemon logs.
216216

217+
The daemon writes one structured JSON line per record to `~/.pitlane/daemon.log`
218+
(timestamp, level, module, message, and any fields) covering startup (version,
219+
protocol version, socket path, effective config), socket claim/stale-endpoint
220+
recovery, driver discovery, connection open/close, shutdown, and unexpected or
221+
handled errors. Growth is bounded: once the file passes `log.rotateBytes` it is
222+
rotated to `daemon.log.1` (replacing any previous generation), so `logs` always
223+
shows the current file with the immediately preceding one prepended.
224+
217225
## `pitlane config [get <key>|set <key> <value>]`
218226

219227
Show the effective configuration (defaults + config file + overrides):
220228
managed and running capacity limits, idle tiers T1/T2/T3, TTLs, disk-pressure
221-
threshold. With no args, prints everything. Running capacity
229+
threshold, and the daemon's log level/rotation cap (`log.level`,
230+
`log.rotateBytes`). With no args, prints everything. Running capacity
222231
uses `limits.maxRunning` globally and `limits.<platform>.maxRunning` for each
223232
driver; both must have room before provisioning or booting a shutdown device.

‎src/cli/index.test.ts‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ import {
2222
errorExitCode,
2323
fallbackRequesterId,
2424
parseDuration,
25+
readLogFile,
2526
runCli,
2627
type CliEnvironment,
2728
type DaemonConnection,
@@ -38,6 +39,33 @@ afterEach(async () => {
3839
);
3940
});
4041

42+
describe("readLogFile", () => {
43+
it("returns just the current log when there is no rotated generation", async () => {
44+
const filesystem = new MemoryFilesystem();
45+
await filesystem.mkdirp("/pitlane");
46+
await filesystem.writeFileAtomic("/pitlane/daemon.log", "current\n");
47+
48+
await expect(readLogFile(filesystem, "/pitlane/daemon.log")).resolves.toBe("current\n");
49+
});
50+
51+
it("prepends the rotated generation so a pre-rotation crash is not lost", async () => {
52+
const filesystem = new MemoryFilesystem();
53+
await filesystem.mkdirp("/pitlane");
54+
await filesystem.writeFileAtomic("/pitlane/daemon.log.1", "rotated\n");
55+
await filesystem.writeFileAtomic("/pitlane/daemon.log", "current\n");
56+
57+
await expect(readLogFile(filesystem, "/pitlane/daemon.log")).resolves.toBe(
58+
"rotated\ncurrent\n",
59+
);
60+
});
61+
62+
it("propagates the read failure when neither file exists", async () => {
63+
const filesystem = new MemoryFilesystem();
64+
65+
await expect(readLogFile(filesystem, "/pitlane/daemon.log")).rejects.toThrow();
66+
});
67+
});
68+
4169
describe("CLI boundary", () => {
4270
it.each([
4371
["QUEUE_TIMEOUT", 10],
@@ -759,6 +787,7 @@ function testConfig(): Config {
759787
ios: { maxDevices: 1, maxRunning: 1 },
760788
maxRunning: 1 + 1,
761789
},
790+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
762791
ramBudget: { androidBytesPerDevice: 4 * gibibyte, iosBytesPerDevice: gibibyte },
763792
};
764793
}

‎src/cli/index.ts‎

Lines changed: 17 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import {
88
NodeFilesystem,
99
NodeIpcTransport,
1010
SystemClock,
11+
type Filesystem,
1112
} from "../ports/index.js";
1213
import { connectDaemon, connectExistingDaemon } from "../daemon-client/client.js";
1314
import { parseRawLeaseGrant } from "../daemon-client/contracts.js";
@@ -118,7 +119,7 @@ function defaultCliEnvironment(env: NodeJS.ProcessEnv = process.env): CliEnviron
118119
if (!(await filesystem.exists(configPath))) return {};
119120
return requireObject(JSON.parse(await filesystem.readFile(configPath)) as unknown);
120121
},
121-
readLogFile: async () => filesystem.readFile(logPath),
122+
readLogFile: async () => readLogFile(filesystem, logPath),
122123
signals: process,
123124
stderr: process.stderr,
124125
stdout: process.stdout,
@@ -731,6 +732,21 @@ function parseConfigValue(value: string): unknown {
731732
return value;
732733
}
733734
}
735+
/**
736+
* Reads the rotated generation (if present) followed by the current log, so a fatal
737+
* crash written just before rotation is never silently lost. `NodeFileLogSink` keeps
738+
* at most one rotated generation at `<logPath>.1`.
739+
*/
740+
export async function readLogFile(filesystem: Filesystem, logPath: string): Promise<string> {
741+
const rotatedPath = `${logPath}.1`;
742+
const segments: string[] = [];
743+
if (await filesystem.exists(rotatedPath)) {
744+
segments.push(await filesystem.readFile(rotatedPath));
745+
}
746+
segments.push(await filesystem.readFile(logPath));
747+
return segments.join("");
748+
}
749+
734750
function requireObject(value: unknown): Record<string, unknown> {
735751
if (typeof value !== "object" || value === null || Array.isArray(value))
736752
throw new Error("Daemon returned an invalid response");

‎src/core/acquisition-planner.test.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ const config: Config = {
2020
maxRunning: 1,
2121
},
2222
ramBudget: { androidBytesPerDevice: 4 * gibibyte, iosBytesPerDevice: gibibyte },
23+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
2324
};
2425

2526
function device(

‎src/core/capacity-coordinator.test.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ const config: Config = {
2020
maxRunning: 2,
2121
},
2222
ramBudget: { androidBytesPerDevice: 4 * gibibyte, iosBytesPerDevice: 1.5 * gibibyte },
23+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
2324
};
2425

2526
function coordinator(): CapacityCoordinator {

‎src/core/capacity.test.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ const config: Config = {
2626
maxRunning: 2,
2727
},
2828
ramBudget: { androidBytesPerDevice: 4 * gibibyte, iosBytesPerDevice: 1.5 * gibibyte },
29+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
2930
};
3031

3132
function withStats(totalRamBytes: number): FakeSystemStats {

‎src/core/cleanup/idle-destroy.test.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ const config: Config = {
1414
maxRunning: 1 + 1,
1515
},
1616
ramBudget: { androidBytesPerDevice: 1, iosBytesPerDevice: 1 },
17+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
1718
};
1819

1920
function view(now: number): RegistryView {

‎src/core/cleanup/idle-shutdown.test.ts‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ const config: Config = {
1414
maxRunning: 1 + 1,
1515
},
1616
ramBudget: { androidBytesPerDevice: 1, iosBytesPerDevice: 1 },
17+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
1718
};
1819

1920
function view(now: number): RegistryView {

‎src/core/config.test.ts‎

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,11 +50,44 @@ describe("loadConfig", () => {
5050
heartbeatIntervalMs: 5 * 60_000,
5151
},
5252
ramBudget: { androidBytesPerDevice: 4 * gibibyte, iosBytesPerDevice: 1.5 * gibibyte },
53+
log: { level: "info", rotateBytes: 5 * 1024 * 1024 },
5354
});
5455
expect(Object.isFrozen(config)).toBe(true);
5556
expect(Object.isFrozen(config.limits)).toBe(true);
5657
});
5758

59+
it("applies a file-level log override", async () => {
60+
const filesystem = new MemoryFilesystem();
61+
await filesystem.mkdirp("/home/agent/.pitlane");
62+
await filesystem.writeFileAtomic(
63+
configPath,
64+
JSON.stringify({ log: { level: "debug", rotateBytes: 1024 } }),
65+
);
66+
67+
const config = await loadConfig({ configPath, filesystem, systemStats: createStats() });
68+
expect(config.log).toEqual({ level: "debug", rotateBytes: 1024 });
69+
});
70+
71+
it("rejects a log level outside the known set", async () => {
72+
const filesystem = new MemoryFilesystem();
73+
await filesystem.mkdirp("/home/agent/.pitlane");
74+
await filesystem.writeFileAtomic(configPath, JSON.stringify({ log: { level: "verbose" } }));
75+
76+
await expect(
77+
loadConfig({ configPath, filesystem, systemStats: createStats() }),
78+
).rejects.toThrow("log.level");
79+
});
80+
81+
it("rejects a non-positive-integer log rotation cap", async () => {
82+
const filesystem = new MemoryFilesystem();
83+
await filesystem.mkdirp("/home/agent/.pitlane");
84+
await filesystem.writeFileAtomic(configPath, JSON.stringify({ log: { rotateBytes: 0 } }));
85+
86+
await expect(
87+
loadConfig({ configPath, filesystem, systemStats: createStats() }),
88+
).rejects.toThrow("log.rotateBytes");
89+
});
90+
5891
it("applies file values over defaults and explicit overrides over file values", async () => {
5992
const filesystem = new MemoryFilesystem();
6093
await filesystem.mkdirp("/home/agent/.pitlane");

0 commit comments

Comments
 (0)