feat(streaming): log session lifecycles and why streamers fail

The session manager logs each session's creation, readiness time and
removal with its reason. A streamer that exits during startup now fails
the start at once instead of after 60 seconds, and the log carries its
exit code and last output; containers are no longer auto-removed, so
that output survives until teardown. A failed start reaches the app as
a 502.

docs/10-features/13-streaming.md

@@ -106,6 +106,11 @@ reachable only from the session manager.
 
 ## Troubleshooting
 
+`docker compose logs session-manager` shows each session as it's created,
+becomes ready (with how long it took) and is removed, with the reason. When a
+streamer fails to start, the log says why: its exit code and its last lines of
+output. The app then reports "game failed to start" to the player.
+
 - **No "Original Flash Player" button, or "needs the Flashpoint Launcher" on
   Java and Shockwave games.** The session manager isn't running, the tokens
   don't match, or it can't resolve the game's launcher; check that Infinity's

streaming/session-manager/src/docker.ts

@@ -25,6 +25,7 @@ export interface DockerDriverOptions {
 const LABEL = 'flashpoint.stream-session';
 const HOME = '/config';
 const READY_TIMEOUT_MS = 60_000;
+const LOG_LINES = 30;
 
 export class DockerDriver implements Driver {
   private readonly docker = new Docker();
@@ -56,7 +57,8 @@ export class DockerDriver implements Driver {
         Binds: [`${flashpointHostPath}:/flashpoint:ro`],
         NetworkMode: network,
         ShmSize: 1024 ** 3,
-        AutoRemove: true,
+        // Not auto-removed, so a container that crashes keeps its output to
+        // report; teardown removes it, and removeAll clears leftovers
       },
     });
   }
@@ -67,7 +69,22 @@ export class DockerDriver implements Driver {
       await container.putArchive(await toTar(saves, this.options.uid, this.options.gid), { path: HOME });
     }
     await container.start();
-    await waitForHttp(this.url(id) + streamPath(id), READY_TIMEOUT_MS);
+    const url = this.url(id) + streamPath(id);
+    try {
+      await waitUntilReady(
+        () => fetch(url).then((res) => res.ok, () => false),
+        async () => {
+          const { State } = await container.inspect();
+          return State.Running ? null : State.ExitCode;
+        },
+        READY_TIMEOUT_MS,
+      );
+    } catch (err) {
+      const output = await container
+        .logs({ stdout: true, stderr: true, tail: LOG_LINES })
+        .then((logs) => dockerLogText(logs as unknown as Buffer), () => '');
+      throw new Error(`${(err as Error).message}${output ? `; last output:\n${output}` : ''}`);
+    }
   }
 
   async getSaves(id: string): Promise<SaveFiles> {
@@ -112,14 +129,44 @@ function containerName(id: string): string {
   return `fp-stream-${id}`;
 }
 
-async function waitForHttp(url: string, timeoutMs: number): Promise<void> {
+/**
+ * Polls until `ready` is true, failing early once `exitCode` reports that the
+ * container has stopped (a number) rather than still running (null).
+ */
+export async function waitUntilReady(
+  ready: () => Promise<boolean>,
+  exitCode: () => Promise<number | null>,
+  timeoutMs: number,
+  intervalMs = 500,
+): Promise<void> {
   const deadline = Date.now() + timeoutMs;
   while (Date.now() < deadline) {
-    const ok = await fetch(url).then((res) => res.ok, () => false);
-    if (ok) {
+    if (await ready()) {
       return;
     }
-    await new Promise((resolve) => setTimeout(resolve, 500));
+    const code = await exitCode();
+    if (code !== null) {
+      throw new Error(`streamer exited with code ${code}`);
+    }
+    await new Promise((resolve) => setTimeout(resolve, intervalMs));
   }
-  throw new Error(`timed out waiting for ${url}`);
+  throw new Error(`streamer not ready after ${timeoutMs / 1000}s`);
+}
+
+/**
+ * Turns Docker's log output into text. Without a TTY, each chunk is framed by
+ * an 8-byte header: stream type, three zero bytes, then the big-endian length.
+ */
+export function dockerLogText(logs: Buffer): string {
+  const framed = logs.length >= 8 && logs[0] <= 2 && logs[1] === 0 && logs[2] === 0 && logs[3] === 0;
+  if (!framed) {
+    return logs.toString('utf8').trimEnd();
+  }
+  const chunks: Buffer[] = [];
+  for (let i = 0; i + 8 <= logs.length; ) {
+    const length = logs.readUInt32BE(i + 4);
+    chunks.push(logs.subarray(i + 8, i + 8 + length));
+    i += 8 + length;
+  }
+  return Buffer.concat(chunks).toString('utf8').trimEnd();
 }

streaming/session-manager/src/sessions.ts

@@ -12,6 +12,9 @@ export interface SessionTimings {
   savesPollMs: number;
 }
 
+/** Where lifecycle events and failures are reported. */
+export type Log = Pick<Console, 'log' | 'error'>;
+
 export const DEFAULT_TIMINGS: SessionTimings = {
   connectTimeoutMs: 120_000,
   idleGraceMs: 30_000,
@@ -46,17 +49,20 @@ export class SessionManager {
   private readonly catalog: Pick<GameCatalog, 'streamSize'>;
   private readonly maxSessions: number;
   private readonly timings: SessionTimings;
+  private readonly log: Log;
 
   constructor(
     driver: Driver,
     catalog: Pick<GameCatalog, 'streamSize'>,
     maxSessions: number,
     timings: SessionTimings = DEFAULT_TIMINGS,
+    log: Log = console,
   ) {
     this.driver = driver;
     this.catalog = catalog;
     this.maxSessions = maxSessions;
     this.timings = timings;
+    this.log = log;
   }
 
   async create(gameId: string): Promise<{ id: string; size: Size }> {
@@ -76,7 +82,8 @@ export class SessionManager {
       this.sessions.delete(id);
       throw err;
     }
-    this.scheduleTeardown(session, this.timings.connectTimeoutMs);
+    this.log.log(`Session ${id}: created for game ${gameId} at ${size.width}x${size.height}`);
+    this.scheduleTeardown(session, this.timings.connectTimeoutMs, 'nobody connected');
     return { id, size };
   }
 
@@ -92,13 +99,16 @@ export class SessionManager {
     }
     session.state = 'starting';
     session.saves = canonical(saves);
+    const started = Date.now();
     try {
       await this.driver.start(id, saves);
     } catch (err) {
-      await this.teardown(id);
-      throw err;
+      this.log.error(`Session ${id}: failed to start: ${(err as Error).message}`);
+      await this.teardown(id, 'failed to start');
+      throw new SessionError(502, 'game failed to start');
     }
     session.state = 'running';
+    this.log.log(`Session ${id}: ready in ${((Date.now() - started) / 1000).toFixed(1)}s`);
     this.startPolling(session);
   }
 
@@ -113,7 +123,7 @@ export class SessionManager {
   socketClosed(id: string): void {
     const session = this.sessions.get(id);
     if (session && --session.sockets === 0) {
-      this.scheduleTeardown(session, this.timings.idleGraceMs);
+      this.scheduleTeardown(session, this.timings.idleGraceMs, 'player left');
     }
   }
 
@@ -125,11 +135,12 @@ export class SessionManager {
     return () => session.listeners.delete(listener);
   }
 
-  async teardown(id: string): Promise<void> {
+  async teardown(id: string, reason = 'requested'): Promise<void> {
     const session = this.sessions.get(id);
     if (!session) {
       return;
     }
+    this.log.log(`Session ${id}: removing (${reason})`);
     this.sessions.delete(id);
     clearTimeout(session.teardownTimer);
     clearInterval(session.pollTimer);
@@ -143,7 +154,7 @@ export class SessionManager {
   }
 
   async teardownAll(): Promise<void> {
-    await Promise.all([...this.sessions.keys()].map((id) => this.teardown(id)));
+    await Promise.all([...this.sessions.keys()].map((id) => this.teardown(id, 'shutting down')));
   }
 
   private get(id: string): Session {
@@ -154,16 +165,16 @@ export class SessionManager {
     return session;
   }
 
-  private scheduleTeardown(session: Session, delayMs: number): void {
+  private scheduleTeardown(session: Session, delayMs: number, reason: string): void {
     clearTimeout(session.teardownTimer);
     session.teardownTimer = setTimeout(() => {
-      this.teardown(session.id).catch((err) => console.error(`Failed to tear down ${session.id}:`, err));
+      this.teardown(session.id, reason).catch((err) => this.log.error(`Session ${session.id}: failed to remove:`, err));
     }, delayMs);
   }
 
   private startPolling(session: Session): void {
     session.pollTimer = setInterval(() => {
-      this.pollSaves(session).catch((err) => console.error(`Failed to read saves for ${session.id}:`, err));
+      this.pollSaves(session).catch((err) => this.log.error(`Session ${session.id}: failed to read saves:`, err));
     }, this.timings.savesPollMs);
   }
 

streaming/session-manager/test/docker.test.ts

@@ -0,0 +1,33 @@
+import assert from 'node:assert/strict';
+import { test } from 'node:test';
+import { dockerLogText, waitUntilReady } from '../src/docker.ts';
+
+test('waitUntilReady resolves once the streamer answers', async () => {
+  let polls = 0;
+  await waitUntilReady(async () => ++polls >= 3, async () => null, 1000, 1);
+  assert.equal(polls, 3);
+});
+
+test('waitUntilReady fails as soon as the streamer exits', async () => {
+  const started = Date.now();
+  await assert.rejects(
+    waitUntilReady(async () => false, async () => 139, 5000, 1),
+    /exited with code 139/,
+  );
+  assert.ok(Date.now() - started < 1000);
+});
+
+test('waitUntilReady gives up after the timeout', async () => {
+  await assert.rejects(waitUntilReady(async () => false, async () => null, 30, 1), /not ready after/);
+});
+
+test('dockerLogText reads framed and plain log output', () => {
+  const frame = (stream: number, text: string) => {
+    const header = Buffer.alloc(8);
+    header[0] = stream;
+    header.writeUInt32BE(Buffer.byteLength(text), 4);
+    return Buffer.concat([header, Buffer.from(text)]);
+  };
+  assert.equal(dockerLogText(Buffer.concat([frame(1, 'starting\n'), frame(2, 'boom\n')])), 'starting\nboom');
+  assert.equal(dockerLogText(Buffer.from('plain output\n')), 'plain output');
+});

streaming/session-manager/test/fakes.ts

@@ -9,6 +9,8 @@ import type { SaveFiles } from '../src/saves.ts';
 export class FakeDriver implements Driver {
   readonly containers = new Map<string, { gameId: string; size: Size; saves: SaveFiles; started: boolean }>();
   readonly removed: string[] = [];
+  /** Makes start() fail with this error, as a crashing streamer would */
+  failStart?: Error;
   private server?: http.Server;
 
   async listen(): Promise<void> {
@@ -27,6 +29,9 @@ export class FakeDriver implements Driver {
   }
 
   async start(id: string, saves: SaveFiles): Promise<void> {
+    if (this.failStart) {
+      throw this.failStart;
+    }
     Object.assign(this.containers.get(id)!, { saves: { ...saves }, started: true });
   }
 
@@ -52,6 +57,13 @@ export const catalog = {
   },
 };
 
+/** Collects log lines instead of printing them */
+export class MemoryLog {
+  readonly lines: string[] = [];
+  log = (...args: unknown[]) => void this.lines.push(args.join(' '));
+  error = (...args: unknown[]) => void this.lines.push(args.join(' '));
+}
+
 export const fastTimings = { connectTimeoutMs: 300, idleGraceMs: 100, savesPollMs: 20 };
 
 export const sleep = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms));

streaming/session-manager/test/sessions.test.ts

@@ -1,7 +1,7 @@
 import assert from 'node:assert/strict';
 import { test } from 'node:test';
 import { SessionError, SessionManager } from '../src/sessions.ts';
-import { catalog, FakeDriver, fastTimings, sleep } from './fakes.ts';
+import { catalog, FakeDriver, fastTimings, MemoryLog, sleep } from './fakes.ts';
 
 test('rejects unstreamable games and enforces the session cap', async () => {
   const sessions = new SessionManager(new FakeDriver(), catalog, 1, fastTimings);
@@ -58,3 +58,27 @@ test('starts with the given saves, pushes changes, and ends with a final push',
   await sessions.teardown(id);
   assert.deepEqual(seen, [{ 'cookies.txt': 'YQ==' }, { 'cookies.txt': 'Yg==' }, { 'cookies.txt': 'Yw==' }, null]);
 });
+
+test('logs a session from creation to removal', async () => {
+  const log = new MemoryLog();
+  const sessions = new SessionManager(new FakeDriver(), catalog, 4, fastTimings, log);
+  const { id } = await sessions.create('java');
+  await sessions.start(id, {});
+  await sessions.teardown(id, 'player left');
+  assert.equal(log.lines.length, 3);
+  assert.match(log.lines[0], new RegExp(`Session ${id}: created for game java at 472x354`));
+  assert.match(log.lines[1], /ready in \d+\.\ds/);
+  assert.match(log.lines[2], /removing \(player left\)/);
+});
+
+test('reports a streamer that fails to start, and removes it', async () => {
+  const driver = new FakeDriver();
+  driver.failStart = new Error('streamer exited with code 1; last output:\nno display');
+  const log = new MemoryLog();
+  const sessions = new SessionManager(driver, catalog, 4, fastTimings, log);
+  const { id } = await sessions.create('java');
+  await assert.rejects(sessions.start(id, {}), (e: SessionError) => e.status === 502);
+  assert.equal(sessions.has(id), false);
+  assert.deepEqual(driver.removed, [id]);
+  assert.ok(log.lines.some((line) => line.includes('failed to start: streamer exited with code 1') && line.includes('no display')));
+});