Fix active and match timer drift between status polls

Persist occupancy transitions with telemetry and carry timer anchors through live updates. Cover delayed polling, lobby rejoining, and lifecycle boundaries with regression tests.

Fixes #47
This commit is contained in:
2026-09-27 23:29:04 -04:00
parent b904ddbc48
commit 2fa3792482
8 changed files with 210 additions and 15 deletions
+8
View File
@@ -23,6 +23,14 @@ Historical scoreboards remain visible and are labeled separately from live count
RCON diagnostics retain their own results. Telemetry does not report ping or player RCON diagnostics retain their own results. Telemetry does not report ping or player
capacity, so those fields remain unknown in telemetry-only observations. capacity, so those fields remain unknown in telemetry-only observations.
**Active** measures time since the lobby was first observed with players;
**Match** measures time since the script's `game_start` was received. Telemetry
records occupancy changes immediately, so a later heartbeat or status poll does
not move the active timer forward. A new match keeps the active timer if the
lobby stays occupied. An empty report clears the match timer and begins the
inactive period; a later join begins a new active period. These are observed
times, not exact player connection timestamps.
## Fleet overview ## Fleet overview
Fleet searches server names, map names, and the full player roster. Filter occupied, Fleet searches server names, map names, and the full player roster. Filter occupied,
+12 -4
View File
@@ -50,14 +50,22 @@ export function selectServerObservation<T extends ServerObservation>(server: T,
const containerFresh = server.container_state === 'running' && freshStatusTimestamp(checked ?? null, now); const containerFresh = server.container_state === 'running' && freshStatusTimestamp(checked ?? null, now);
if (containerFresh && report?.server === server.name && freshTelemetry(report, now, server.telemetry_after)) { if (containerFresh && report?.server === server.name && freshTelemetry(report, now, server.telemetry_after)) {
const players = report.players.length; const players = report.players.length;
// New reports carry persisted anchors through both SSE and HTTP. Keep
// the fallback for telemetry saved before server timing was included.
const timing = report.timing?.server ?? {
activeSince: server.active_since ?? report.receivedAt,
inactiveSince: server.inactive_since ?? report.receivedAt,
gameStartedAt: report.event === 'game_start' ? report.receivedAt : server.game_started_at,
gameEndedAt: report.event === 'game_start' ? null : report.event === 'game_end' ? report.receivedAt : server.game_ended_at
};
return { ...result, health: 'online', status_source: 'telemetry', last_players: players, return { ...result, health: 'online', status_source: 'telemetry', last_players: players,
last_map: report.map, last_seen_at: report.receivedAt, last_error: null, last_map: report.map, last_seen_at: report.receivedAt, last_error: null,
roster: report.players.map(player => ({ num: null, score: 'score' in player ? player.score : null, roster: report.players.map(player => ({ num: null, score: 'score' in player ? player.score : null,
ping: null, guid: player.guid, name: player.name })), ping: null, guid: player.guid, name: player.name })),
active_since: players > 0 ? server.active_since ?? report.receivedAt : null, active_since: players > 0 ? timing.activeSince : null,
inactive_since: players === 0 ? server.inactive_since ?? report.receivedAt : null, inactive_since: players === 0 ? timing.inactiveSince : null,
game_started_at: players === 0 ? null : report.event === 'game_start' ? report.receivedAt : server.game_started_at, game_started_at: players === 0 ? null : timing.gameStartedAt,
game_ended_at: players === 0 || report.event === 'game_start' ? null : report.event === 'game_end' ? report.receivedAt : server.game_ended_at }; game_ended_at: players === 0 ? null : timing.gameEndedAt };
} }
const after = !server.telemetry_after || Date.parse(raw.last_seen_at ?? '') > Date.parse(server.telemetry_after); const after = !server.telemetry_after || Date.parse(raw.last_seen_at ?? '') > Date.parse(server.telemetry_after);
const fresh = after && freshStatusTimestamp(raw.last_seen_at, now) && !raw.last_error; const fresh = after && freshStatusTimestamp(raw.last_seen_at, now) && !raw.last_error;
+3 -3
View File
@@ -89,9 +89,9 @@ CREATE TABLE IF NOT EXISTS servers (
created_by TEXT, -- 'ui' | operator identifier created_by TEXT, -- 'ui' | operator identifier
destroyed_at TEXT, -- ISO ts when tombstoned (row usually deleted; kept as safety net) destroyed_at TEXT, -- ISO ts when tombstoned (row usually deleted; kept as safety net)
-- Occupancy + match timers. active_since / inactive_since are mutually -- Occupancy + match timers. active_since / inactive_since are mutually
-- exclusive: exactly one is non-null while a server is reachable. RCON -- exclusive. Accepted telemetry records transitions immediately; status
-- outages do NOT clear either — timers survive transient unreachability -- polls provide the RCON fallback. Outages do NOT clear either — timers
-- and resume from the same anchor when the server comes back. -- survive transient unreachability and resume from the same anchor.
active_since TEXT, -- ISO ts of last 0 -> >0 player transition active_since TEXT, -- ISO ts of last 0 -> >0 player transition
inactive_since TEXT, -- ISO ts of last >0 -> 0 player transition inactive_since TEXT, -- ISO ts of last >0 -> 0 player transition
game_started_at TEXT, -- receipt time of the script's game_start game_started_at TEXT, -- receipt time of the script's game_start
+23 -6
View File
@@ -1,7 +1,8 @@
import { db } from '../db/index.js'; import { db } from '../db/index.js';
import type { GameTelemetry } from '../../telemetry.js'; import type { GameTelemetry, ServerTiming } from '../../telemetry.js';
import { MIN_RECORDED_ROUND } from '../../match-history.js'; import { MIN_RECORDED_ROUND } from '../../match-history.js';
import { recordLeaderboardTelemetry } from './leaderboard-ingest.js'; import { recordLeaderboardTelemetry } from './leaderboard-ingest.js';
import { latestGameSubmission } from './status-evidence.js';
export function listTelemetry(): GameTelemetry[] { export function listTelemetry(): GameTelemetry[] {
const rows = db().prepare(`SELECT t.payload FROM server_telemetry t JOIN servers s ON s.name = t.server const rows = db().prepare(`SELECT t.payload FROM server_telemetry t JOIN servers s ON s.name = t.server
@@ -16,11 +17,30 @@ export function saveTelemetry(report: GameTelemetry): GameTelemetry {
const row = handle.prepare('SELECT payload FROM server_telemetry WHERE server = ?').get(report.server) as { payload: string | null } | undefined; const row = handle.prepare('SELECT payload FROM server_telemetry WHERE server = ?').get(report.server) as { payload: string | null } | undefined;
const previous: GameTelemetry | undefined = row?.payload ? JSON.parse(row.payload) : undefined; const previous: GameTelemetry | undefined = row?.payload ? JSON.parse(row.payload) : undefined;
recordLeaderboardTelemetry(handle, report); recordLeaderboardTelemetry(handle, report);
// Record each occupancy transition at receipt, before a heartbeat can
// replace game_start or an empty report between status polls.
const after = latestGameSubmission(report.server);
if (!after || Date.parse(report.receivedAt) > Date.parse(after)) {
if (report.players.length > 0) {
handle.prepare('UPDATE servers SET active_since = COALESCE(active_since, ?), inactive_since = NULL WHERE name = ?')
.run(report.receivedAt, report.server);
if (report.event === 'game_start') {
handle.prepare('UPDATE servers SET game_started_at = ?, game_ended_at = NULL WHERE name = ?').run(report.receivedAt, report.server);
} else if (report.event === 'game_end') {
handle.prepare('UPDATE servers SET game_ended_at = ? WHERE name = ?').run(report.receivedAt, report.server);
}
} else {
handle.prepare(`UPDATE servers SET active_since = NULL, inactive_since = COALESCE(inactive_since, ?),
game_started_at = NULL, game_ended_at = NULL WHERE name = ?`).run(report.receivedAt, report.server);
}
}
const serverTiming = handle.prepare(`SELECT active_since AS activeSince, inactive_since AS inactiveSince,
game_started_at AS gameStartedAt, game_ended_at AS gameEndedAt FROM servers WHERE name = ?`).get(report.server) as ServerTiming;
const match = handle.prepare('SELECT id FROM leaderboard_matches WHERE server = ? ORDER BY id DESC LIMIT 1').get(report.server) as { id: number }; const match = handle.prepare('SELECT id FROM leaderboard_matches WHERE server = ? ORDER BY id DESC LIMIT 1').get(report.server) as { id: number };
const sameMatch = previous?.timing?.matchId === match.id; const sameMatch = previous?.timing?.matchId === match.id;
// A gap beyond the normal heartbeat window cannot establish continuity. // A gap beyond the normal heartbeat window cannot establish continuity.
const continuous = previous && Date.parse(report.receivedAt) - Date.parse(previous.receivedAt) <= 120_000; const continuous = previous && Date.parse(report.receivedAt) - Date.parse(previous.receivedAt) <= 120_000;
report = { ...report, timing: { matchId: match.id, players: Object.fromEntries(report.players.map(player => { report = { ...report, timing: { matchId: match.id, server: serverTiming, players: Object.fromEntries(report.players.map(player => {
const prior = continuous ? previous?.timing?.players[player.guid] : undefined; const prior = continuous ? previous?.timing?.players[player.guid] : undefined;
return [player.guid, { return [player.guid, {
serverJoinedAt: prior?.serverJoinedAt ?? report.receivedAt, serverJoinedAt: prior?.serverJoinedAt ?? report.receivedAt,
@@ -32,10 +52,7 @@ export function saveTelemetry(report: GameTelemetry): GameTelemetry {
VALUES (?, ?, ?, ?, ?) ON CONFLICT(server) DO UPDATE SET VALUES (?, ?, ?, ?, ?) ON CONFLICT(server) DO UPDATE SET
round = excluded.round, players = excluded.players, received_at = excluded.received_at, payload = excluded.payload`) round = excluded.round, players = excluded.players, received_at = excluded.received_at, payload = excluded.payload`)
.run(report.server, report.event === 'game_start' ? 0 : report.round, report.players.length, report.receivedAt, JSON.stringify(report)); .run(report.server, report.event === 'game_start' ? 0 : report.round, report.players.length, report.receivedAt, JSON.stringify(report));
if (report.event === 'game_start') { if (report.event === 'game_end') {
handle.prepare('UPDATE servers SET game_started_at = ?, game_ended_at = NULL WHERE name = ?').run(report.receivedAt, report.server);
} else if (report.event === 'game_end') {
handle.prepare('UPDATE servers SET game_ended_at = ? WHERE name = ?').run(report.receivedAt, report.server);
// Legacy betas also take match completion directly from the script. // Legacy betas also take match completion directly from the script.
if (report.round >= MIN_RECORDED_ROUND) handle.prepare(`UPDATE beta_servers SET match_seen_at = ? WHERE server = ? AND server_deleted_at IS NULL AND stage = 'awaiting-match' if (report.round >= MIN_RECORDED_ROUND) handle.prepare(`UPDATE beta_servers SET match_seen_at = ? WHERE server = ? AND server_deleted_at IS NULL AND stage = 'awaiting-match'
AND healthy_at <= ? AND beta_id IN (SELECT id FROM betas WHERE state = 'running')`) AND healthy_at <= ? AND beta_id IN (SELECT id FROM betas WHERE state = 'running')`)
+9 -1
View File
@@ -22,9 +22,17 @@ export interface PlayerTiming {
roundStarted: number | null; roundStarted: number | null;
} }
/** Server-owned anchors, included so successive live reports keep the same timers. */
export interface ServerTiming {
activeSince: string | null;
inactiveSince: string | null;
gameStartedAt: string | null;
gameEndedAt: string | null;
}
export type GameTelemetry = GameEvent & { export type GameTelemetry = GameEvent & {
receivedAt: string; receivedAt: string;
timing?: { matchId: number; players: Record<string, PlayerTiming> }; timing?: { matchId: number; players: Record<string, PlayerTiming>; server?: ServerTiming };
}; };
/** Validate the four script payloads; beta state is never part of the protocol. */ /** Validate the four script payloads; beta state is never part of the protocol. */
+90 -1
View File
@@ -17,7 +17,7 @@ beforeEach(async () => {
vi.clearAllMocks(); vi.clearAllMocks();
fixture = await newFixture(['unregistered-folder']); fixture = await newFixture(['unregistered-folder']);
}); });
afterEach(async () => { await fixture.cleanup(); }); afterEach(async () => { vi.useRealTimers(); await fixture.cleanup(); });
async function setup() { async function setup() {
const { db } = await import('../../src/lib/server/db/index.js'); const { db } = await import('../../src/lib/server/db/index.js');
@@ -85,6 +85,95 @@ describe('database fleet and container readiness', () => {
expect(getServer('managed')?.game_ended_at).toBeNull(); expect(getServer('managed')?.game_ended_at).toBeNull();
}); });
it('keeps the first occupied report as the active timer when more telemetry arrives before polling', async () => {
const { inspect, rcon, fanoutStatus, getServer } = await setup();
const { GET } = await import('../../src/routes/api/servers/+server.js');
const { subscribe } = await import('../../src/lib/server/pipeline/bus.js');
const startedAt = Date.parse('2026-09-27T12:00:00Z');
const at = (seconds: number) => new Date(startedAt + seconds * 1000).toISOString();
vi.useFakeTimers({ toFake: ['Date'] });
vi.setSystemTime(startedAt);
inspect.mockResolvedValue({ ok: true, state: 'running' });
expect((await postTelemetry(gameEvent('game_start', 0, 1, 'managed'))).status).toBe(200);
expect(getServer('managed')).toMatchObject({ active_since: at(0), inactive_since: null, game_started_at: at(0) });
vi.setSystemTime(startedAt + 19_000);
const heartbeat = await (await postTelemetry(gameEvent('heartbeat', 2, 1, 'managed'))).json();
expect(heartbeat.telemetry.timing.server).toEqual({
activeSince: at(0), inactiveSince: null, gameStartedAt: at(0), gameEndedAt: null
});
vi.setSystemTime(startedAt + 30_000);
const events: unknown[] = [];
const unsubscribe = subscribe(event => events.push(event));
try { await fanoutStatus(); } finally { unsubscribe(); }
expect(rcon).not.toHaveBeenCalled();
expect((await (await GET()).json()).servers[0]).toMatchObject({
active_since: at(0), game_started_at: at(0), last_seen_at: at(19)
});
expect(events).toContainEqual(expect.objectContaining({ type: 'server-status', entries: [expect.objectContaining({
activeSince: at(0), gameStartedAt: at(0), lastSeenAt: at(19)
})] }));
const { closeDb } = await import('../../src/lib/server/db/index.js');
closeDb();
expect((await (await GET()).json()).servers[0]).toMatchObject({ active_since: at(0), game_started_at: at(0) });
});
it('preserves occupancy observed by RCON before game-start telemetry', async () => {
const { inspect, rcon, fanoutStatus, getServer } = await setup();
const startedAt = Date.parse('2026-09-27T12:00:00Z');
const at = (seconds: number) => new Date(startedAt + seconds * 1000).toISOString();
vi.useFakeTimers({ toFake: ['Date'] });
vi.setSystemTime(startedAt - 20_000);
inspect.mockResolvedValue({ ok: true, state: 'running' });
rcon.mockResolvedValue({ ok: true, endpoint: { host: 'localhost', port: 28960 }, rawReply: 'status',
status: { players: 1, map: 'zombie_theater', gametype: 'zom', roster: [] } });
await fanoutStatus();
expect(getServer('managed')).toMatchObject({ active_since: at(-20), game_started_at: null });
vi.setSystemTime(startedAt);
const start = await (await postTelemetry(gameEvent('game_start', 0, 1, 'managed'))).json();
expect(start.telemetry.timing.server).toEqual({
activeSince: at(-20), inactiveSince: null, gameStartedAt: at(0), gameEndedAt: null
});
expect(getServer('managed')).toMatchObject({ active_since: at(-20), inactive_since: null, game_started_at: at(0) });
});
it('records an empty lobby and rejoin between status polls without restoring the old match', async () => {
const { inspect, fanoutStatus, getServer } = await setup();
const { GET } = await import('../../src/routes/api/servers/+server.js');
const startedAt = Date.parse('2026-09-27T12:00:00Z');
const at = (seconds: number) => new Date(startedAt + seconds * 1000).toISOString();
vi.useFakeTimers({ toFake: ['Date'] });
vi.setSystemTime(startedAt);
inspect.mockResolvedValue({ ok: true, state: 'running' });
await postTelemetry(gameEvent('game_start', 0, 1, 'managed'));
vi.setSystemTime(startedAt + 10_000);
await postTelemetry(gameEvent('game_end', 2, 1, 'managed'));
vi.setSystemTime(startedAt + 11_000);
const empty = await (await postTelemetry(gameEvent('heartbeat', 0, 0, 'managed'))).json();
expect(empty.telemetry.timing.server).toEqual({
activeSince: null, inactiveSince: at(11), gameStartedAt: null, gameEndedAt: null
});
expect(getServer('managed')).toMatchObject({
active_since: null, inactive_since: at(11), game_started_at: null, game_ended_at: null
});
vi.setSystemTime(startedAt + 15_000);
const rejoin = await (await postTelemetry(gameEvent('heartbeat', 1, 1, 'managed'))).json();
expect(rejoin.telemetry.timing.server).toEqual({
activeSince: at(15), inactiveSince: null, gameStartedAt: null, gameEndedAt: null
});
expect(getServer('managed')).toMatchObject({
active_since: at(15), inactive_since: null, game_started_at: null, game_ended_at: null
});
vi.setSystemTime(startedAt + 30_000);
await fanoutStatus();
expect((await (await GET()).json()).servers[0]).toMatchObject({
active_since: at(15), inactive_since: null, game_started_at: null, game_ended_at: null
});
});
it('waits for game_start telemetry after log initialization and player joins', async () => { it('waits for game_start telemetry after log initialization and player joins', async () => {
const { inspect, rcon, fanoutStatus, getServer } = await setup(); const { inspect, rcon, fanoutStatus, getServer } = await setup();
const { GET } = await import('../../src/routes/api/servers/+server.js'); const { GET } = await import('../../src/routes/api/servers/+server.js');
+24
View File
@@ -13,6 +13,30 @@ afterEach(async () => fixture.cleanup());
const payload = gameEvent('round_change', 17); const payload = gameEvent('round_change', 17);
it('does not let a request received before a lifecycle submission restore cleared timers', async () => {
const { db } = await import('../../src/lib/server/db/index.js');
const { saveTelemetry } = await import('../../src/lib/server/fleet/telemetry.js');
const { getServer } = await import('../../src/lib/server/fleet/servers.js');
const at = (seconds: number) => new Date(Date.parse('2026-09-20T12:00:00Z') + seconds * 1000).toISOString();
db().prepare('INSERT INTO restart_rollout (server, requested_at) VALUES (?, ?)').run(payload.server, at(10));
for (const seconds of [9, 10]) {
saveTelemetry({ ...gameEvent('game_start'), receivedAt: at(seconds) });
expect(getServer(payload.server)).toMatchObject({ active_since: null, game_started_at: null });
}
const current = saveTelemetry({ ...gameEvent('heartbeat', 2), receivedAt: at(11) });
expect(current.timing?.server).toEqual({ activeSince: at(11), inactiveSince: null, gameStartedAt: null, gameEndedAt: null });
});
it('generates timer anchors on the server instead of accepting client-supplied timing', async () => {
const response = await post({ ...gameEvent('game_start'), receivedAt: '2000-01-01T00:00:00Z',
timing: { server: { activeSince: '2000-01-01T00:00:00Z' } } });
const { telemetry } = await response.json();
expect(response.status).toBe(200);
expect(telemetry.receivedAt).not.toBe('2000-01-01T00:00:00Z');
expect(telemetry.timing.server).toEqual({ activeSince: telemetry.receivedAt, inactiveSince: null,
gameStartedAt: telemetry.receivedAt, gameEndedAt: null });
});
it('persists player timing across matches and resets after absence or a telemetry gap', async () => { it('persists player timing across matches and resets after absence or a telemetry gap', async () => {
const { saveTelemetry, listTelemetry } = await import('../../src/lib/server/fleet/telemetry.js'); const { saveTelemetry, listTelemetry } = await import('../../src/lib/server/fleet/telemetry.js');
const { closeDb } = await import('../../src/lib/server/db/index.js'); const { closeDb } = await import('../../src/lib/server/db/index.js');
+41
View File
@@ -2,6 +2,7 @@ import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
import { get } from 'svelte/store'; import { get } from 'svelte/store';
import { freshServer, matchesFleet, type FleetServer } from '../../src/lib/fleet-overview.js'; import { freshServer, matchesFleet, type FleetServer } from '../../src/lib/fleet-overview.js';
import type { ServerStatus } from '../../src/lib/ui/stores/servers.js'; import type { ServerStatus } from '../../src/lib/ui/stores/servers.js';
import type { GameEvent, ServerTiming } from '../../src/lib/telemetry.js';
import { gameEvent } from '../helpers/telemetry.js'; import { gameEvent } from '../helpers/telemetry.js';
vi.mock('$app/environment', () => ({ browser: true })); vi.mock('$app/environment', () => ({ browser: true }));
@@ -66,6 +67,46 @@ async function setup() {
} }
describe('Fleet report clock', () => { describe('Fleet report clock', () => {
it('keeps persisted occupancy and match anchors through live reports before the next status poll', async () => {
const at = (seconds: number) => new Date(epoch + seconds * 1000).toISOString();
snapshot.servers = [server(epoch, { container_state: 'running', container_checked_at: at(0) })];
const { fleetServers } = await setup();
const report = (event: GameEvent['event'], seconds: number, players: number, timing: ServerTiming) => {
source.dispatchEvent(new MessageEvent('server-telemetry', { data: JSON.stringify({ serverNow: epoch + seconds * 1000,
entries: [{ ...gameEvent(event, 2, players), receivedAt: at(seconds),
timing: { matchId: 1, players: {}, server: timing } }] }) }));
return get(fleetServers)[0];
};
const active = { activeSince: at(1), inactiveSince: null, gameStartedAt: at(1), gameEndedAt: null };
report('game_start', 1, 1, active);
expect(report('heartbeat', 20, 1, active)).toMatchObject({
active_since: at(1), inactive_since: null, game_started_at: at(1), game_ended_at: null
});
const ended = { ...active, gameEndedAt: at(30) };
report('game_end', 30, 1, ended);
expect(report('heartbeat', 31, 1, ended).game_ended_at).toBe(at(30));
const nextMatch = { ...active, gameStartedAt: at(32) };
report('game_start', 32, 1, nextMatch);
expect(report('heartbeat', 33, 1, nextMatch)).toMatchObject({
active_since: at(1), game_started_at: at(32), game_ended_at: null
});
expect(report('heartbeat', 34, 0, { activeSince: null, inactiveSince: at(34), gameStartedAt: null, gameEndedAt: null }))
.toMatchObject({ active_since: null, inactive_since: at(34), game_started_at: null, game_ended_at: null });
expect(report('heartbeat', 35, 1, { activeSince: at(35), inactiveSince: null, gameStartedAt: null, gameEndedAt: null }))
.toMatchObject({ active_since: at(35), inactive_since: null, game_started_at: null, game_ended_at: null });
});
it('restores timers from a telemetry snapshot even when the browser missed game_start', async () => {
const startedAt = new Date(epoch - 19_000).toISOString();
snapshot.servers = [server(epoch, { container_state: 'running', container_checked_at: new Date(epoch).toISOString() })];
const { fleetServers } = await setup();
source.dispatchEvent(new MessageEvent('server-telemetry', { data: JSON.stringify({ serverNow: epoch, snapshot: true,
entries: [{ ...gameEvent('heartbeat', 2, 1), receivedAt: new Date(epoch).toISOString(),
timing: { matchId: 1, players: {}, server: { activeSince: startedAt, inactiveSince: null,
gameStartedAt: startedAt, gameEndedAt: null } } }] }) }));
expect(get(fleetServers)[0]).toMatchObject({ active_since: startedAt, game_started_at: startedAt });
});
it('updates count and roster immediately from telemetry and expires them together', async () => { it('updates count and roster immediately from telemetry and expires them together', async () => {
snapshot.servers = [server(epoch, { container_state: 'running', container_checked_at: new Date(epoch).toISOString(), last_players: 4 })]; snapshot.servers = [server(epoch, { container_state: 'running', container_checked_at: new Date(epoch).toISOString(), last_players: 4 })];
const { fleetServers, uiNow } = await setup(); const { fleetServers, uiNow } = await setup();