josh/electric-cherry
1
0
Fork 0
Code Issues 18 Pull Requests Actions Packages Projects Releases Wiki Activity

Add real time, match duration, and round context to chat

Browse Source
This commit is contained in:
josh
2026-10-02 13:21:55 -04:00
parent 65d3a99846
commit d7b3e124e6
8 changed files with 505 additions and 26 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tests/unit/game-chat.test.ts
+119 -1
View File
@@ -1,5 +1,5 @@
import { describe, expect, it } from 'vitest';
import { parseGameChat, parseGameChatTimeline } from '../../src/lib/game-chat.js';
import { enrichGameChatTimeline, parseGameChat, parseGameChatTimeline, type ChatMatch, type ChatRoundReport } from '../../src/lib/game-chat.js';
describe('game chat', () => {
it('extracts say messages and ignores joins', () => {
@@ -78,3 +78,121 @@ describe('game chat', () => {
expect(entries.every(entry => entry.type === 'message')).toBe(true);
});
});
describe('chat time and round context', () => {
const at = (seconds: number) => new Date(Date.parse('2026-10-02T12:00:00Z') + seconds * 1000).toISOString();
const match = (start: number, end: number, overrides: Partial<ChatMatch> = {}): ChatMatch => ({
startedAt: at(start), endedAt: at(end), lastReceivedAt: at(end), status: 'completed', startObserved: true, ...overrides
});
const report = (seconds: number, round: number, overrides: Partial<ChatRoundReport> = {}): ChatRoundReport => ({
receivedAt: at(seconds), event: 'round_change', round, playerCount: 2, ...overrides
});
const say = (time: string, message = 'hello') => `${time} say;abc;0;Player;${message}`;
const unavailable = { realTime: null, matchElapsedMs: null, round: null };
it('anchors to the final log event and uses gameplay start, excluding engine idle time', () => {
const lines = ['60:00 InitGame:', say('62:07'), say('62:15'), '62:30 J;def;1;Other'];
const entries = enrichGameChatTimeline(lines, { mtime: at(150), matches: [match(120, 300)],
reports: [report(125, 3), report(130, 4)] });
expect(entries[1].context).toEqual({ realTime: at(127), matchElapsedMs: 7000, round: 3 });
expect(entries[2].context).toEqual({ realTime: at(135), matchElapsedMs: 15000, round: 4 });
expect(entries[0].context).toEqual({ realTime: at(0), matchElapsedMs: null, round: null });
});
it('associates messages with their own match when the engine clock continues across matches', () => {
const entries = enrichGameChatTimeline(['60:00 InitGame:', say('60:30', 'old'), '61:00 ExitLevel:',
'62:00 InitGame:', say('62:30', 'new')], { mtime: at(150), matches: [match(10, 60), match(130, 200)],
reports: [report(20, 8), report(140, 2)] });
expect(entries[1].context).toEqual({ realTime: at(30), matchElapsedMs: 20000, round: 8 });
expect(entries[4].context).toEqual({ realTime: at(150), matchElapsedMs: 20000, round: 2 });
});
it('does not carry wall time backward across a clock reset on a non-chat line', () => {
const entries = enrichGameChatTimeline([say('80:00', 'old'), '0:00 J;abc;0;Player', say('0:30', 'new')],
{ mtime: at(300), matches: [match(0, 500)], reports: [report(280, 10)] });
expect(entries[0].context).toEqual(unavailable);
// The preceding match cannot leak past the inferred new match at 12:04:30.
expect(entries[2].context).toEqual({ realTime: at(300), matchElapsedMs: null, round: null });
});
it('treats repeated zero-time InitGame and untimed lifecycle events as unanchored earlier sessions', () => {
for (const boundary of ['0:00 InitGame:', 'InitGame:', 'ShutdownGame:']) {
const entries = enrichGameChatTimeline([say('0:00', 'old'), boundary, say('0:30', 'new')],
{ mtime: at(300), matches: [], reports: [] });
expect(entries[0].context).toEqual(unavailable);
expect(entries.at(-1)?.context.realTime).toBe(at(300));
}
});
it('can enrich a tail without InitGame but never invents a start for a partially observed match', () => {
const options = { mtime: at(150), matches: [match(100, 300)], reports: [report(140, 8)] };
expect(enrichGameChatTimeline([say('800:00')], options)[0].context)
.toEqual({ realTime: at(150), matchElapsedMs: 50000, round: 8 });
options.matches[0].startObserved = false;
expect(enrichGameChatTimeline([say('800:00')], options)[0].context)
.toEqual({ realTime: at(150), matchElapsedMs: null, round: 8 });
});
it('does not treat old or future reports, game starts, or the highest round as the message round', () => {
for (const reports of [[report(29, 5)], [report(151, 10)],
[report(140, 0, { event: 'game_start', round: null })], []]) {
expect(enrichGameChatTimeline([say('62:30')], { mtime: at(150), matches: [match(0, 300)], reports })[0].context)
.toMatchObject({ realTime: at(150), round: null });
}
});
it('does not continue match context after an empty report, game end, or an unreported new log session', () => {
for (const change of [report(140, 8, { playerCount: 0 }), report(140, 8, { event: 'game_end' })]) {
expect(enrichGameChatTimeline([say('62:30')], { mtime: at(150), matches: [match(0, 300)],
reports: [report(130, 7), change] })[0].context)
.toEqual({ realTime: at(150), matchElapsedMs: null, round: null });
}
for (const boundary of ['62:00 InitGame:', '62:00 ExitLevel:', 'InitGame:']) {
expect(enrichGameChatTimeline([boundary, say('62:30')], { mtime: at(150), matches: [match(0, 300)],
reports: [report(130, 7)] }).at(-1)?.context)
.toEqual({ realTime: at(150), matchElapsedMs: null, round: null });
}
});
it('bounds active matches by recent evidence and interrupted matches by their last observation', () => {
for (const recorded of [match(0, 300, { status: 'active', endedAt: null, lastReceivedAt: at(29) }),
match(0, 300, { status: 'interrupted', endedAt: null, lastReceivedAt: at(140) })]) {
expect(enrichGameChatTimeline([say('62:30')], { mtime: at(150), matches: [recorded], reports: [report(29, 7)] })[0].context)
.toEqual({ realTime: at(150), matchElapsedMs: null, round: null });
}
});
it('keeps active context from fresh heartbeats even when leaderboard deduplication stopped its clock', () => {
expect(enrichGameChatTimeline([say('62:30')], { mtime: at(150),
matches: [match(0, 300, { status: 'active', endedAt: null, lastReceivedAt: at(10) })],
reports: [report(140, 7, { event: 'heartbeat' })] })[0].context)
.toEqual({ realTime: at(150), matchElapsedMs: 150000, round: 7 });
});
it('allows a start before the first observed event following an implicit clock reset', () => {
expect(enrichGameChatTimeline([say('80:00'), '0:05 J;abc;0;Player', say('0:20')], {
mtime: at(300), matches: [match(280, 400)], reports: [report(290, 1)]
}).at(-1)?.context).toEqual({ realTime: at(300), matchElapsedMs: 20000, round: 1 });
});
it('uses the same latest game_start as fleet when the leaderboard deduplicates start retries', () => {
const entries = enrichGameChatTimeline([say('62:00'), say('62:30')], { mtime: at(150),
matches: [match(0, 300)], reports: [report(0, 0, { event: 'game_start', round: null }),
report(130, 0, { event: 'game_start', round: null }), report(140, 1)] });
expect(entries[0].context.matchElapsedMs).toBe(120000);
expect(entries[1].context).toEqual({ realTime: at(150), matchElapsedMs: 20000, round: 1 });
expect(enrichGameChatTimeline(['62:00 InitGame:', say('62:30')], { mtime: at(150),
matches: [match(0, 300)], reports: [report(130, 0, { event: 'game_start', round: null }), report(140, 1)]
}).at(-1)?.context).toEqual({ realTime: at(150), matchElapsedMs: 20000, round: 1 });
});
it('leaves context unknown without a usable final write timestamp', () => {
for (const mtime of [null, 'bad date']) {
expect(enrichGameChatTimeline([say('62:30')], { mtime, matches: [match(0, 300)], reports: [report(140, 7)] })[0].context)
.toEqual(unavailable);
}
expect(enrichGameChatTimeline([say('62:30'), 'untimed write'], { mtime: at(150), matches: [], reports: [] })[0].context)
.toEqual(unavailable);
expect(enrichGameChatTimeline([], { mtime: at(150), matches: [], reports: [] })).toEqual([]);
});
});
tests/unit/server-chat.test.ts
+144
View File
@@ -0,0 +1,144 @@
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
import { mkdir, utimes, writeFile } from 'node:fs/promises';
import { join } from 'node:path';
import { newFixture, type Fixture } from '../helpers/fixture.js';
import { gameEvent } from '../helpers/telemetry.js';
import type { GameEvent } from '../../src/lib/telemetry.js';
const SERVER = 't5_zombie_theater_1';
const T6_SERVER = 't6_zombie_town_1';
let fixture: Fixture;
let baseline: number;
const at = (seconds: number) => new Date(baseline + seconds * 1000).toISOString();
beforeEach(async () => {
vi.resetModules();
baseline = Math.floor(Date.now() / 1000) * 1000 - 600_000;
fixture = await newFixture([SERVER, T6_SERVER]);
const { seedServerRegistry } = await import('../../src/lib/server/fleet/servers.js');
const { db } = await import('../../src/lib/server/db/index.js');
await seedServerRegistry();
db().prepare('UPDATE servers SET created_at = ?').run(at(-120));
});
afterEach(async () => {
vi.restoreAllMocks();
await fixture.cleanup();
});
async function log(lines: string[], lastWrite = 60, server = SERVER, filename?: string) {
const folder = join(server.startsWith('t6_') ? fixture.t6 : fixture.t5, server, 'logs');
await mkdir(folder, { recursive: true });
const path = join(folder, filename ?? (server.startsWith('t6_') ? 'games_zm.log' : 'games_sp.log'));
await writeFile(path, lines.join('\n') + '\n');
await utimes(path, new Date(at(lastWrite)), new Date(at(lastWrite)));
}
async function report(event: GameEvent['event'], seconds: number, round = 1, status = 200, diagnostic = true) {
const value = gameEvent(event, round, 1, SERVER);
if (status === 200) {
const { saveTelemetry } = await import('../../src/lib/server/fleet/telemetry.js');
saveTelemetry({ ...value, receivedAt: at(seconds) });
}
if (diagnostic) {
const { recordTelemetryRequest } = await import('../../src/lib/server/fleet/telemetry-requests.js');
recordTelemetryRequest({ value, receivedAt: at(seconds), status,
error: status === 200 ? null : 'Rejected request', contentType: 'application/json' });
}
}
async function get(server = SERVER) {
const { GET } = await import('../../src/routes/api/servers/[name]/chat/+server.js');
return GET({ params: { name: server } });
}
describe('server chat API', () => {
it('keeps real timestamps and historical match context stable across refreshes', async () => {
await report('game_start', 0);
await report('round_change', 40, 4);
await report('round_change', 45, 99, 400);
await log(['60:50 say;abc;0;Player;hello', '61:00 J;abc;0;Player']);
const response = await get();
const body = await response.json();
expect(response.status).toBe(200);
expect(response.headers.get('cache-control')).toBe('no-store');
expect(body).toMatchObject({ ok: true, missing: false, entries: [
{ type: 'message', message: { player: 'Player', message: 'hello' },
context: { realTime: at(50), matchElapsedMs: 50_000, round: 4 } }
] });
expect(JSON.stringify(body)).not.toContain('headshots');
vi.spyOn(Date, 'now').mockReturnValue(baseline + 900_000);
expect(await (await get()).json()).toEqual(body);
});
it('reads the correct game log for each game', async () => {
await log(['1:00 say;abc;0;T5 player;t5 message']);
await log(['1:00 say;abc;0;Wrong;wrong t5 file'], 60, SERVER, 'games_zm.log');
await log(['1:00 say;abc;0;T6 player;t6 message'], 60, T6_SERVER);
await log(['1:00 say;abc;0;Wrong;wrong t6 file'], 60, T6_SERVER, 'games_sp.log');
expect((await (await get()).json()).entries[0].message.message).toBe('t5 message');
expect((await (await get(T6_SERVER)).json()).entries[0].message.message).toBe('t6 message');
});
it('returns an empty successful response until the game log exists', async () => {
expect(await (await get()).json()).toEqual({ ok: true, entries: [], missing: true });
});
it('rejects unknown and destroyed servers even when files remain', async () => {
expect((await get('t5_zombie_theater_99')).status).toBe(404);
await log(['1:00 say;abc;0;Player;hello']);
const { db } = await import('../../src/lib/server/db/index.js');
db().prepare('UPDATE servers SET destroyed_at = ? WHERE name = ?').run(at(60), SERVER);
expect((await get()).status).toBe(404);
});
it('rejects registered names that escape the server directory', async () => {
const { db } = await import('../../src/lib/server/db/index.js');
db().prepare('INSERT INTO servers (name, komodo_name) VALUES (?, ?)').run('..', '..');
expect((await get('..')).status).toBe(400);
});
it('reports read failures without returning server filesystem paths', async () => {
const logs = await import('../../src/lib/server/fleet/logs.js');
vi.spyOn(logs, 'tailLog').mockRejectedValue(new Error('read failed at /private/server/log'));
vi.spyOn(console, 'error').mockImplementation(() => {});
const response = await get();
expect(response.status).toBe(500);
expect(await response.json()).toEqual({ ok: false, reason: 'Could not read server chat' });
});
it('keeps latest accepted gameplay available when diagnostic logging was unavailable', async () => {
await report('game_start', 0, 1, 200, false);
await report('heartbeat', 40, 1, 200, false);
await log(['60:50 say;abc;0;Player;first round', '61:00 J;abc;0;Player']);
const body = await (await get()).json();
expect(body.entries).toHaveLength(1);
expect(body.entries[0].context).toEqual({ realTime: at(50), matchElapsedMs: 50_000, round: 1 });
});
it('does not reuse round diagnostics after their retention window', async () => {
await report('game_start', 0);
await report('heartbeat', 40, 4);
await log(['60:50 say;abc;0;Player;older message', '61:00 J;abc;0;Player']);
vi.spyOn(Date, 'now').mockReturnValue(baseline + 8 * 86_400_000);
const body = await (await get()).json();
expect(body.entries[0].context).toEqual({ realTime: at(50), matchElapsedMs: 50_000, round: null });
});
it('does not associate retained messages with a deleted server incarnation', async () => {
await report('game_start', 0);
await report('heartbeat', 40, 8);
const { db } = await import('../../src/lib/server/db/index.js');
db().prepare('DELETE FROM servers WHERE name = ?').run(SERVER);
db().prepare(`INSERT INTO servers (name, komodo_name, game, map, created_at)
VALUES (?, ?, 't5', 'zombie_theater', ?)`).run(SERVER, SERVER, at(70));
await report('game_start', 80);
await report('heartbeat', 90, 2);
await log(['60:50 say;abc;0;Player;previous server', '61:40 say;abc;0;Player;current server'], 100);
const body = await (await get()).json();
const messages = body.entries.filter((entry: { type: string }) => entry.type === 'message');
expect(messages).toHaveLength(2);
expect(messages[0].context).toEqual({ realTime: at(50), matchElapsedMs: null, round: null });
expect(messages[1].context).toEqual({ realTime: at(100), matchElapsedMs: 20_000, round: 2 });
});
});