Read chat logs incrementally and drain retention (Refs #62)
This commit is contained in:
@@ -0,0 +1,56 @@
|
||||
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
|
||||
import { newFixture, type Fixture } from '../helpers/fixture.js';
|
||||
|
||||
let fixture: Fixture;
|
||||
beforeEach(async () => { vi.resetModules(); fixture = await newFixture([]); });
|
||||
afterEach(async () => { await fixture.cleanup(); });
|
||||
|
||||
async function setup() {
|
||||
const api = await import('../../src/lib/server/hosts/index.js');
|
||||
const { db } = await import('../../src/lib/server/db/index.js');
|
||||
const host = api.createHost({ name: 'Log host' });
|
||||
const operation = api.queueHostOperation(host.id, 'logs.read', { path: 'logs/games_sp.log' });
|
||||
return { ...api, host, operation, db };
|
||||
}
|
||||
|
||||
describe('transient log results', () => {
|
||||
it.each([
|
||||
{ lines: ['private log body'], size: 17, mtime: '2026-10-08T12:00:00Z', truncated: false },
|
||||
{ contentBase64: Buffer.from('private log body').toString('base64'), size: 17, reset: false, cursor: { offset: 17 } }
|
||||
])('delivers full replies to current readers while storing only metadata', async result => {
|
||||
const api = await setup();
|
||||
const first = api.waitHostOperationStatus(api.operation.id);
|
||||
const second = api.waitHostOperation(api.operation.id);
|
||||
const receipt = api.reportHostOperationStatus(api.host.id, api.operation.id, { state: 'completed', result });
|
||||
expect((await first).result).toEqual(result);
|
||||
expect((await second).result).toEqual(result);
|
||||
expect(receipt.result).toMatchObject({ retained: false, size: 17 });
|
||||
expect(api.getHostOperation(api.operation.id)?.result).toEqual(receipt.result);
|
||||
const stored = api.db().prepare('SELECT result FROM ec_host_operations WHERE id=?').get(api.operation.id);
|
||||
expect(JSON.stringify(stored)).not.toMatch(/private log body|contentBase64|cursor|"lines"/);
|
||||
expect(api.db().prepare("SELECT * FROM file_blob_references WHERE owner_type='operation-result' AND owner_id=?").all(api.operation.id)).toEqual([]);
|
||||
// Completed reads cannot serve a stale body, including duplicate receipts.
|
||||
await expect(api.waitHostOperationStatus(api.operation.id)).rejects.toThrow('no longer available');
|
||||
api.reportHostOperationStatus(api.host.id, api.operation.id, { state: 'completed', result });
|
||||
await expect(api.waitHostOperationStatus(api.operation.id)).rejects.toThrow('no longer available');
|
||||
});
|
||||
|
||||
it('preserves missing-log results and operation failures', async () => {
|
||||
const api = await setup();
|
||||
const missing = api.waitHostOperationStatus(api.operation.id);
|
||||
api.reportHostOperationStatus(api.host.id, api.operation.id, { state: 'completed', result: null });
|
||||
expect((await missing).result).toBeNull();
|
||||
const failed = api.queueHostOperation(api.host.id, 'logs.read', {});
|
||||
const failure = api.waitHostOperationStatus(failed.id);
|
||||
api.reportHostOperationStatus(api.host.id, failed.id, { state: 'failed', error: 'Read failed' });
|
||||
expect(await failure).toMatchObject({ state: 'failed', error: 'Read failed' });
|
||||
});
|
||||
|
||||
it('discards bodies arriving after the reader has timed out', async () => {
|
||||
const api = await setup();
|
||||
await expect(api.waitHostOperationStatus(api.operation.id, 0)).rejects.toThrow();
|
||||
api.reportHostOperationStatus(api.host.id, api.operation.id, { state: 'completed', result: { lines: ['late body'] } });
|
||||
expect(api.getHostOperation(api.operation.id)?.result).toEqual({ retained: false, lineCount: 1 });
|
||||
await expect(api.waitHostOperationStatus(api.operation.id)).rejects.toThrow('no longer available');
|
||||
});
|
||||
});
|
||||
@@ -39,6 +39,37 @@ async function setup() {
|
||||
}
|
||||
|
||||
describe('routine host observation retention', () => {
|
||||
it('drains more than one batch while yielding and preserving recent or failed operations', async () => {
|
||||
const api = await setup();
|
||||
const { drainRetention } = await import('../../src/lib/server/retention.js');
|
||||
const retained = [api.add('logs.read', { age: 0 }), api.add('logs.read', { state: 'failed' }), api.add('instance.restart')];
|
||||
api.handle.transaction(() => {
|
||||
const insert = api.handle.prepare(`INSERT INTO ec_host_operations
|
||||
(id,host_id,kind,payload,state,created_at,updated_at,observation_success)
|
||||
VALUES(?,?,'logs.read','{}','completed',?,?,1)`);
|
||||
for (let i = 0; i < 1501; i++) insert.run(`read-${i}`, api.host.id, at(2 * day), at(2 * day));
|
||||
})();
|
||||
let yielded = false;
|
||||
setImmediate(() => { yielded = true; });
|
||||
expect(await drainRetention()).toBe(1501);
|
||||
expect(yielded).toBe(true);
|
||||
expect((api.handle.prepare('SELECT id FROM ec_host_operations').all() as { id: string }[]).map(row => row.id).sort()).toEqual(retained.sort());
|
||||
expect(await drainRetention()).toBe(0);
|
||||
});
|
||||
|
||||
it('strips existing log bodies in batches without deleting recent or protected history', async () => {
|
||||
const api = await setup();
|
||||
const { drainRetention, setRetentionControl } = await import('../../src/lib/server/retention.js');
|
||||
const ids = Array.from({ length: 53 }, () => api.add('logs.read', { age: 0 }));
|
||||
setRetentionControl({ category: 'observation', id: ids[0], protected: true });
|
||||
api.handle.prepare("UPDATE ec_host_operations SET result=? WHERE kind='logs.read'")
|
||||
.run(JSON.stringify({ lines: ['legacy log contents'], size: 20, truncated: false }));
|
||||
expect(await drainRetention()).toBe(0);
|
||||
for (const id of ids) expect(api.getHostOperation(id)?.result).toEqual({ retained: false, lineCount: 1, size: 20, truncated: false });
|
||||
expect(api.handle.prepare("SELECT value FROM settings WHERE key='log_history_metadata_v1'").get()).toEqual({ value: '1' });
|
||||
expect(api.handle.pragma('foreign_key_check')).toEqual([]);
|
||||
});
|
||||
|
||||
it('removes aged successful reads, manifests, and read-only RCON while retaining failures, actions, and recent evidence', async () => {
|
||||
const api = await setup();
|
||||
const removed = ['host.inspect', 'instance.inspect', 'files.read', 'files.stat', 'files.list', 'files.manifest', 'logs.read']
|
||||
|
||||
+66
-2
@@ -1,5 +1,5 @@
|
||||
import { describe, expect, it, beforeEach, afterEach } from 'vitest';
|
||||
import { mkdirSync, rmSync, writeFileSync } from 'node:fs';
|
||||
import { appendFileSync, mkdirSync, renameSync, rmSync, statSync, utimesSync, writeFileSync } from 'node:fs';
|
||||
import { resolve } from 'node:path';
|
||||
import { tmpdir } from 'node:os';
|
||||
|
||||
@@ -12,7 +12,7 @@ process.env.REL_DEST = 'runtime/plutonium/storage/t5/raw/scripts/sp';
|
||||
process.env.BETA_ARCHIVE_DIR = resolve(TMP_ROOT, 'beta-archive');
|
||||
process.env.DB_PATH = resolve(TMP_ROOT, 'test.db');
|
||||
|
||||
const { resolveLogPath, tailLog, isLogKey } = await import(
|
||||
const { resolveLogPath, tailLog, readLogChunk, isLogKey } = await import(
|
||||
'../../src/lib/server/fleet/logs.js'
|
||||
);
|
||||
|
||||
@@ -94,3 +94,67 @@ describe('tailLog', () => {
|
||||
expect(tail?.lines).toEqual(['a', 'b', 'c']);
|
||||
});
|
||||
});
|
||||
|
||||
describe('incremental log reads', () => {
|
||||
const path = resolve(LOG_DIR, 'games_sp.log');
|
||||
async function read(cursor?: import('../../src/lib/server/fleet/logs.js').LogCursor) {
|
||||
const chunk = await readLogChunk(path, cursor);
|
||||
if (!chunk || !('cursor' in chunk)) throw new Error('Expected a byte chunk');
|
||||
return { ...chunk, bytes: Buffer.from(chunk.contentBase64, 'base64') };
|
||||
}
|
||||
|
||||
it('reads only appended bytes and returns no body for unchanged files', async () => {
|
||||
expect(await readLogChunk(path)).toBeNull();
|
||||
writeFileSync(path, 'first\n');
|
||||
const first = await read();
|
||||
expect(first.bytes.toString()).toBe('first\n');
|
||||
expect(first.reset).toBe(true);
|
||||
const unchanged = await read(first.cursor);
|
||||
expect(unchanged.contentBase64).toBe('');
|
||||
expect(unchanged.cursor).toEqual(first.cursor);
|
||||
appendFileSync(path, 'café\n');
|
||||
const appended = await read(first.cursor);
|
||||
expect(appended.bytes.toString()).toBe('café\n');
|
||||
expect(appended.reset).toBe(false);
|
||||
expect(appended.cursor.offset).toBe(Buffer.byteLength('first\ncafé\n'));
|
||||
});
|
||||
|
||||
it('resets after rotation, truncation and copy-truncate regrowth with a restored mtime', async () => {
|
||||
const header = 'same game header\n'.repeat(30);
|
||||
writeFileSync(path, header + 'original\n');
|
||||
let chunk = await read();
|
||||
renameSync(path, path + '.1');
|
||||
writeFileSync(path, header + 'rotated!\n');
|
||||
chunk = await read(chunk.cursor);
|
||||
expect(chunk.reset).toBe(true);
|
||||
expect(chunk.bytes.toString()).toBe(header + 'rotated!\n');
|
||||
const mtime = statSync(path).mtime;
|
||||
writeFileSync(path, header + 'rewritten and longer\n');
|
||||
utimesSync(path, mtime, mtime);
|
||||
chunk = await read(chunk.cursor);
|
||||
expect(chunk.reset).toBe(true);
|
||||
expect(chunk.bytes.toString()).toBe(header + 'rewritten and longer\n');
|
||||
writeFileSync(path, 'short\n');
|
||||
chunk = await read(chunk.cursor);
|
||||
expect(chunk.reset).toBe(true);
|
||||
expect(chunk.bytes.toString()).toBe('short\n');
|
||||
});
|
||||
|
||||
it('bounds initial reads and drains appended backlogs even when the file stops changing', async () => {
|
||||
const window = 256 * 1024;
|
||||
writeFileSync(path, 'x'.repeat(window + 10));
|
||||
const initial = await read();
|
||||
expect(initial.bytes.length).toBe(window);
|
||||
expect(initial.truncated).toBe(true);
|
||||
const appended = Buffer.from('y'.repeat(window + 20));
|
||||
appendFileSync(path, appended);
|
||||
const first = await read(initial.cursor);
|
||||
const second = await read(first.cursor);
|
||||
expect(first.reset).toBe(false);
|
||||
expect(first.bytes.length).toBe(window);
|
||||
expect(first.cursor.offset).toBeLessThan(first.size);
|
||||
expect(second.bytes.length).toBe(20);
|
||||
expect(Buffer.concat([first.bytes, second.bytes])).toEqual(appended);
|
||||
expect((await read(second.cursor)).contentBase64).toBe('');
|
||||
});
|
||||
});
|
||||
|
||||
@@ -6,10 +6,10 @@ let fixture: Fixture;
|
||||
beforeEach(async () => { vi.resetModules(); fixture = await newFixture([]); });
|
||||
afterEach(async () => { await fixture.cleanup(); });
|
||||
|
||||
async function setup() {
|
||||
async function setup(capabilities: string[] = []) {
|
||||
const hosts = await import('../../src/lib/server/hosts/index.js');
|
||||
const host = hosts.createHost({ name: 'Observation host' });
|
||||
hosts.enrollHost(hosts.createEnrollment(host.id).token, { protocolVersion: 1 });
|
||||
hosts.enrollHost(hosts.createEnrollment(host.id).token, { protocolVersion: 1, capabilities });
|
||||
const { db } = await import('../../src/lib/server/db/index.js');
|
||||
db().prepare("INSERT INTO servers(name) VALUES('test')").run();
|
||||
db().prepare(`INSERT INTO native_instances(id,server,host_id,library_id,image,port,created_at)
|
||||
@@ -20,6 +20,19 @@ async function setup() {
|
||||
}
|
||||
|
||||
describe('overlapping native observations', () => {
|
||||
it.each([false, true])('negotiates incremental log reads with agent support: %s', async incremental => {
|
||||
const api = await setup(incremental ? ['logs.read-offset'] : []);
|
||||
const { nativeLogChunk } = await import('../../src/lib/server/backends/files.js');
|
||||
const cursor = { fileId: '1:2', offset: 3, size: 3, modified: '4', anchorLength: 3, anchorHash: 'hash' };
|
||||
const request = nativeLogChunk(join(fixture.t5, 'test', 'logs/games_sp.log'), cursor);
|
||||
const operation = api.listHostOperations(api.host.id)[0];
|
||||
expect(operation.payload).toEqual({ path: 'logs/games_sp.log', ...(incremental ? { mode: 'incremental', cursor } : { lines: 2000 }) });
|
||||
const result = incremental ? { contentBase64: '', cursor, reset: false } : { lines: ['legacy tail'] };
|
||||
api.reportHostOperationStatus(api.host.id, operation.id, { state: 'completed', result });
|
||||
expect(await request).toEqual(result);
|
||||
expect(api.getHostOperation(operation.id)?.result).toMatchObject({ retained: false });
|
||||
});
|
||||
|
||||
it.each(['files.read', 'files.list', 'files.stat', 'files.manifest', 'logs.read', 'instance.inspect'])('shares %s only until completion', async kind => {
|
||||
const api = await setup();
|
||||
const requests = Array.from({ length: 4 }, () => api.nativeRequest(api.instance, kind, { path: 'same' }));
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
|
||||
import { mkdir, rm, utimes, writeFile } from 'node:fs/promises';
|
||||
import { appendFile, mkdir, rm, 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';
|
||||
@@ -53,6 +53,78 @@ async function get(server = SERVER) {
|
||||
}
|
||||
|
||||
describe('server chat API', () => {
|
||||
it('buffers partial UTF-8 lines and avoids context queries when the log is unchanged', async () => {
|
||||
await report('game_start', 0);
|
||||
await report('heartbeat', 40, 4);
|
||||
await log(['60:50 say;abc;0;Player;first'], 50);
|
||||
expect((await (await get()).json()).entries).toHaveLength(1);
|
||||
const { db } = await import('../../src/lib/server/db/index.js');
|
||||
const prepare = vi.spyOn(db(), 'prepare');
|
||||
await get();
|
||||
expect(prepare.mock.calls.some(([sql]) => sql.includes('FROM telemetry_requests'))).toBe(false);
|
||||
expect(prepare.mock.calls.some(([sql]) => sql.includes('last_received_at AS lastReceivedAt'))).toBe(false);
|
||||
prepare.mockRestore();
|
||||
const path = join(fixture.t5, SERVER, 'logs/games_sp.log');
|
||||
const line = Buffer.from('61:00 say;abc;0;Player;café\n');
|
||||
await appendFile(path, line.subarray(0, -2)); // Split inside é, before the newline.
|
||||
await utimes(path, new Date(at(60)), new Date(at(60)));
|
||||
expect((await (await get()).json()).entries).toHaveLength(1);
|
||||
await appendFile(path, line.subarray(-2));
|
||||
await utimes(path, new Date(at(60)), new Date(at(60)));
|
||||
const body = await (await get()).json();
|
||||
expect(body.entries.map((entry: any) => entry.message.message)).toEqual(['first', 'café']);
|
||||
expect(body.entries[1].context.realTime).toBe(at(60));
|
||||
expect((await (await get()).json()).entries).toEqual(body.entries);
|
||||
});
|
||||
|
||||
it('retries appended bytes if archiving fails before publishing the cursor', async () => {
|
||||
await report('game_start', 0);
|
||||
await report('heartbeat', 40, 4);
|
||||
await log(['60:50 say;abc;0;Player;first'], 50);
|
||||
await get();
|
||||
const path = join(fixture.t5, SERVER, 'logs/games_sp.log');
|
||||
await appendFile(path, '61:00 say;abc;0;Player;retry me\n');
|
||||
await utimes(path, new Date(at(60)), new Date(at(60)));
|
||||
const { db } = await import('../../src/lib/server/db/index.js');
|
||||
const handle = db(), original = handle.prepare.bind(handle);
|
||||
const prepare = vi.spyOn(handle, 'prepare').mockImplementation((sql: string) => {
|
||||
if (sql.includes('INSERT INTO match_chat')) throw new Error('Temporary database failure');
|
||||
return original(sql);
|
||||
});
|
||||
vi.spyOn(console, 'error').mockImplementation(() => {});
|
||||
expect((await get()).status).toBe(500);
|
||||
prepare.mockRestore();
|
||||
expect((await (await get()).json()).entries.map((entry: any) => entry.message.message)).toEqual(['first', 'retry me']);
|
||||
});
|
||||
|
||||
it('skips empty, stopped and offline servers and collects one last time after players leave', async () => {
|
||||
const { db } = await import('../../src/lib/server/db/index.js');
|
||||
const { createHost } = await import('../../src/lib/server/hosts/index.js');
|
||||
const logs = await import('../../src/lib/server/fleet/logs.js');
|
||||
const read = vi.spyOn(logs, 'readLogChunk');
|
||||
const { collectFleetChat } = await import('../../src/lib/server/fleet/chat.js');
|
||||
db().prepare("UPDATE servers SET last_players=0,container_state='running'").run();
|
||||
await collectFleetChat();
|
||||
expect(read).not.toHaveBeenCalled();
|
||||
db().prepare('UPDATE servers SET last_players=1 WHERE name=?').run(SERVER);
|
||||
await log(['60:50 say;abc;0;Player;playing'], 50);
|
||||
await collectFleetChat();
|
||||
expect(read).toHaveBeenCalledTimes(1);
|
||||
db().prepare('UPDATE servers SET last_players=0 WHERE name=?').run(SERVER);
|
||||
await collectFleetChat();
|
||||
await collectFleetChat();
|
||||
expect(read).toHaveBeenCalledTimes(2);
|
||||
db().prepare("UPDATE servers SET last_players=1,container_state='stopped' WHERE name=?").run(SERVER);
|
||||
await collectFleetChat();
|
||||
expect(read).toHaveBeenCalledTimes(2);
|
||||
const host = createHost({ name: 'Offline' });
|
||||
db().prepare("UPDATE servers SET container_state='running' WHERE name=?").run(SERVER);
|
||||
db().prepare(`INSERT INTO native_instances(id,server,host_id,library_id,image,port,created_at)
|
||||
VALUES('offline-instance',?,?,'library','image',28960,?)`).run(SERVER, host.id, at(0));
|
||||
await collectFleetChat();
|
||||
expect(read).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
it('keeps real timestamps and historical match context stable across refreshes', async () => {
|
||||
await report('game_start', 0);
|
||||
await report('round_change', 40, 4);
|
||||
@@ -100,7 +172,7 @@ describe('server chat API', () => {
|
||||
|
||||
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(logs, 'readLogChunk').mockRejectedValue(new Error('read failed at /private/server/log'));
|
||||
vi.spyOn(console, 'error').mockImplementation(() => {});
|
||||
const response = await get();
|
||||
expect(response.status).toBe(500);
|
||||
|
||||
@@ -6,7 +6,7 @@ vi.mock('../../src/lib/server/pipeline/beta-runner.js', () => ({ betaTick: vi.fn
|
||||
vi.mock('../../src/lib/server/maintenance/index.js', () => ({ runMaintenance: vi.fn() }));
|
||||
vi.mock('../../src/lib/server/game-files/index.js', () => ({ cleanupControllerLibraries: vi.fn(async () => {}) }));
|
||||
vi.mock('../../src/lib/server/provisioning/worker.js', () => ({ processProvisioning: vi.fn(async () => {}) }));
|
||||
vi.mock('../../src/lib/server/retention.js', () => ({ pruneHistory: vi.fn(), pruneSampleHistory: vi.fn() }));
|
||||
vi.mock('../../src/lib/server/retention.js', () => ({ drainRetention: vi.fn(async () => 0) }));
|
||||
vi.mock('../../src/lib/server/fleet/chat.js', () => ({ collectFleetChat: vi.fn(async () => {}) }));
|
||||
|
||||
function deferred() {
|
||||
@@ -58,19 +58,16 @@ describe('independent provisioning scheduling', () => {
|
||||
|
||||
it('runs retention at most every five minutes across ticks and explicit kicks', async () => {
|
||||
const s = await setup();
|
||||
const { pruneHistory, pruneSampleHistory } = await import('../../src/lib/server/retention.js');
|
||||
const { drainRetention } = await import('../../src/lib/server/retention.js');
|
||||
vi.useFakeTimers();
|
||||
try {
|
||||
s.startWorker();
|
||||
expect(pruneHistory).toHaveBeenCalledTimes(1);
|
||||
expect(pruneSampleHistory).toHaveBeenCalledTimes(1);
|
||||
expect(drainRetention).toHaveBeenCalledTimes(1);
|
||||
await vi.advanceTimersByTimeAsync(285_000);
|
||||
await s.kick();
|
||||
expect(pruneHistory).toHaveBeenCalledTimes(1);
|
||||
expect(pruneSampleHistory).toHaveBeenCalledTimes(1);
|
||||
expect(drainRetention).toHaveBeenCalledTimes(1);
|
||||
await vi.advanceTimersByTimeAsync(15_000);
|
||||
expect(pruneHistory).toHaveBeenCalledTimes(2);
|
||||
expect(pruneSampleHistory).toHaveBeenCalledTimes(2);
|
||||
expect(drainRetention).toHaveBeenCalledTimes(2);
|
||||
expect(s.process.mock.calls.length).toBeGreaterThan(2);
|
||||
} finally {
|
||||
s.stopWorker(); s.background.resolve();
|
||||
@@ -80,6 +77,27 @@ describe('independent provisioning scheduling', () => {
|
||||
}
|
||||
});
|
||||
|
||||
it('keeps a retention backlog running without overlapping it or blocking provisioning', async () => {
|
||||
const s = await setup();
|
||||
const { drainRetention } = await import('../../src/lib/server/retention.js');
|
||||
const cleanup = deferred();
|
||||
vi.mocked(drainRetention).mockImplementationOnce(async () => { await cleanup.promise; return 1501; });
|
||||
vi.useFakeTimers();
|
||||
try {
|
||||
s.startWorker();
|
||||
await vi.advanceTimersByTimeAsync(600_000);
|
||||
expect(drainRetention).toHaveBeenCalledTimes(1);
|
||||
expect(s.process.mock.calls.length).toBeGreaterThan(2);
|
||||
cleanup.resolve();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
} finally {
|
||||
s.stopWorker(); cleanup.resolve(); s.background.resolve();
|
||||
await vi.advanceTimersByTimeAsync(0);
|
||||
vi.useRealTimers();
|
||||
await vi.waitFor(() => expect(s.workerActivity()).toEqual([]));
|
||||
}
|
||||
});
|
||||
|
||||
it('runs controller library cleanup on worker ticks without overlapping a slow cleanup', async () => {
|
||||
const s = await setup();
|
||||
const { cleanupControllerLibraries } = await import('../../src/lib/server/game-files/index.js');
|
||||
|
||||
Reference in New Issue
Block a user