Survive a first full crawl: poll, time out on silence, retry downloads

The first full crawl with the file manager ran 14 minutes, downloading every
file once, and broke in three ways:

- `schulcloud refresh` reported "fetch failed" for a crawl that was
  succeeding: Node's fetch abandons a response without headers after five
  minutes. POST /api/refresh takes wait:false and the CLI polls /api/status;
  refresh_index answers after 50 s and leaves the crawl running, and
  index_status says when a first crawl is under way.
- Downloads were bounded by the 30 s request timeout, which cut 11 MB scans
  off mid-transfer. They now time out on 30 s of silence instead.
- Failures were recorded once and never retried. A download failure is now
  retried on the next crawl while an extraction failure stays final, and PDF
  text containing NUL, which Postgres refuses, is stripped.

On the re-crawl all six failed files succeeded; only two videos above the
mirror cap stay metadata-only, by design. 137 tests.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
MechaCat02
2026-09-16 20:19:16 +02:00
parent bed3923902
commit 3e44e66dde
11 changed files with 310 additions and 28 deletions

View File

@@ -147,6 +147,18 @@ These cost real time to discover; `docs/API.md` has the full list with evidence.
- **Never swallow a per-item crawl error.** Board failures used to be caught and
dropped, so the index lost whole boards while the crawl reported success —
which is how the 20-id limit went unnoticed. They go into `Snapshot.failures`.
- **Record failures by kind, or transient ones become permanent.** Every failed
file used to be marked done, so a timeout was never retried. A *download*
failure is now recorded with `retry: true` and the next crawl tries again; an
*extraction* failure is final. Two causes found on the first full crawl of a
real account: downloads bounded by the 30 s request timeout (11 MB scans cut
off mid-transfer — downloads now time out on 30 s of *silence*), and PDF text
containing NUL, which Postgres `text` refuses — stripped in `recordFileText`.
- **A full crawl can outlast one HTTP request.** The first one with the file
manager took 14 minutes (every file downloaded once); Node's fetch abandons a
response without headers after 5. `POST /api/refresh` takes `wait: false` and
the CLI polls `/api/status`; `refresh_index` returns after 50 s and leaves the
crawl running. Don't reintroduce a caller that waits on a full crawl inline.
- **`GET /lessons/{id}/tasks` is a bare array whose items carry no id.** Not the
`{data,total}` envelope, and `LessonLinkedTaskResponse` has no id field at
all. A topic-attached task is thus unidentifiable from the API and invisible

View File

@@ -49,6 +49,10 @@ alongside courses, with their files under the room's name rather than a course's
`refresh` asks the server to re-read Schulcloud. Pass `--course` when you know
what changed: that is a handful of requests, where a full re-crawl reads every
course. The server refuses a repeat within a minute unless you pass `--force`.
A full re-crawl can take many minutes — the first one downloads every file,
file-manager folders included — so `refresh` starts it and then polls the
server's status, printing a note every half minute, rather than holding one
request open (which Node's fetch abandons after five minutes).
### The file manager (`fs`)

View File

@@ -236,7 +236,14 @@ async function refresh(flags: Flags): Promise<number> {
const api = new ApiClient(await loadCliConfig());
const scope = flags.course ? String(flags.course) : undefined;
process.stderr.write(`Asking the server to re-crawl ${scope ? `course ${scope}` : 'everything'}\n`);
const result = (await api.refresh(scope, Boolean(flags.force))) as {
let lastNote = 0;
const result = (await api.refresh(scope, Boolean(flags.force), (seconds) => {
// A note every half minute, so a long first crawl does not look hung.
if (seconds - lastNote >= 30) {
lastNote = seconds;
process.stderr.write(` still crawling… ${seconds}s\n`);
}
})) as {
crawlId: number; courses: number; files: number; mirrored: number; extracted: number;
skipped: number; durationMs: number; joined?: boolean;
};

View File

@@ -103,13 +103,41 @@ export class ApiClient {
return (await (await this.request(`/api/manifest${query}`)).json()) as Manifest;
}
async refresh(courseId?: string, force = false): Promise<Record<string, unknown>> {
/**
* Starts a re-crawl and waits for it by polling the server's status.
*
* Not one long request: a crawl that downloads every course file can run for
* many minutes, and fetch gives up after five without response headers —
* which reported "fetch failed" for a crawl that was succeeding.
*/
async refresh(
courseId?: string,
force = false,
onWaiting?: (seconds: number) => void,
): Promise<Record<string, unknown>> {
const response = await this.request('/api/refresh', {
method: 'POST',
headers: { 'content-type': 'application/json' },
body: JSON.stringify({ courseId, force }),
body: JSON.stringify({ courseId, force, wait: false }),
});
return (await response.json()) as Record<string, unknown>;
const started = (await response.json()) as { joined?: boolean; startedAt?: string | null };
const began = Date.now();
for (;;) {
await new Promise((resolve) => setTimeout(resolve, 3000));
const status = (await this.status()) as {
indexer?: { running?: boolean; lastResult?: Record<string, unknown>; lastError?: string } | null;
};
const indexer = status.indexer;
if (!indexer) throw new ApiError(503, 'The server has no indexer.');
if (indexer.running) {
onWaiting?.(Math.round((Date.now() - began) / 1000));
continue;
}
if (indexer.lastError) throw new ApiError(502, `The re-crawl failed on the server: ${indexer.lastError}`);
if (!indexer.lastResult) throw new ApiError(502, 'The re-crawl finished without a result.');
return { ...indexer.lastResult, joined: started.joined === true };
}
}
/** Streams one file's bytes. */

View File

@@ -129,7 +129,12 @@ export class SchulcloudClient {
* bearer form is fetched with redirects off, so a login bounce or a hop to a
* third host is seen rather than silently followed with credentials attached.
*/
private async request(url: URL, accept: string, auth: 'bearer' | 'cookie' | 'none' = 'bearer'): Promise<Response> {
private async request(
url: URL,
accept: string,
auth: 'bearer' | 'cookie' | 'none' = 'bearer',
options: { idleTimeout?: boolean } = {},
): Promise<Response> {
let lastError: unknown;
const headers: Record<string, string> = { Accept: accept };
if (auth === 'bearer') headers.Authorization = `Bearer ${this.config.jwt}`;
@@ -139,13 +144,15 @@ export class SchulcloudClient {
if (attempt > 0) await delay(backoffMs(attempt));
let response: Response;
const deadline = options.idleTimeout ? idleDeadline(this.config.requestTimeoutMs) : undefined;
try {
response = await fetch(url, {
headers,
signal: AbortSignal.timeout(this.config.requestTimeoutMs),
signal: deadline?.signal ?? AbortSignal.timeout(this.config.requestTimeoutMs),
redirect: auth === 'bearer' ? 'follow' : 'manual',
});
} catch (error) {
deadline?.stop();
// Connection reset or timeout: worth one more try, since every call
// here is an idempotent GET.
lastError = error;
@@ -153,7 +160,8 @@ export class SchulcloudClient {
continue;
}
if (response.ok) return response;
if (response.ok) return deadline ? deadline.watch(response) : response;
deadline?.stop();
const body = await response.text().catch(() => '');
// A pre-signed URL's query string is its credential, so it never goes
@@ -192,7 +200,7 @@ export class SchulcloudClient {
*/
async getBytes(path: string, fallbackName: string): Promise<DownloadedFile> {
const url = this.url(path);
const response = await this.request(url, '*/*');
const response = await this.request(url, '*/*', 'bearer', { idleTimeout: true });
return this.readCapped(response, fallbackName);
}
@@ -639,7 +647,7 @@ export class SchulcloudClient {
*/
async openSignedUrl(signedUrl: string): Promise<Response> {
const target = checkSignedUrl(signedUrl, this.config.baseUrl);
return this.request(target, '*/*', 'none');
return this.request(target, '*/*', 'none', { idleTimeout: true });
}
private async legacyRequest(path: string, accept: string): Promise<Response> {
@@ -657,6 +665,50 @@ export class SchulcloudClient {
}
}
/**
* A timeout that measures silence rather than total time, for downloads.
*
* The request timeout is right for an API call and wrong for a file: it bounds
* the whole transfer, so an 11 MB scan from a slow storage host was cut off at
* 30 seconds while its bytes were still arriving — four files on the live
* account, recorded as failures. Here the clock starts over with every chunk,
* so only a transfer that stalls is abandoned.
*/
function idleDeadline(ms: number) {
const controller = new AbortController();
const expire = () => controller.abort(new Error(`no data received for ${Math.round(ms / 1000)}s`));
let timer = setTimeout(expire, ms);
// Never the reason a process stays alive: a caller that stops reading early
// (the download cap) leaves the last timer behind.
timer.unref();
const rearm = () => {
clearTimeout(timer);
timer = setTimeout(expire, ms);
timer.unref();
};
const stop = () => clearTimeout(timer);
const watch = (response: Response): Response => {
if (!response.body) {
stop();
return response;
}
rearm();
const body = response.body.pipeThrough(
new TransformStream<Uint8Array, Uint8Array>({
transform(chunk, output) {
rearm();
output.enqueue(chunk);
},
flush() {
stop();
},
}),
);
return new Response(body, { status: response.status, statusText: response.statusText, headers: response.headers });
};
return { signal: controller.signal, stop, watch };
}
/**
* The file-manager listing routes, and nothing else.
*

View File

@@ -62,9 +62,22 @@ export function createApiRouter(services: Services): Router {
router.post('/refresh', express.json({ limit: '16kb' }), async (req: Request, res: Response) => {
if (!services.indexer) return res.status(503).json({ error: 'no_index' });
const body = (req.body ?? {}) as { courseId?: string; force?: boolean };
const body = (req.body ?? {}) as { courseId?: string; force?: boolean; wait?: boolean };
try {
const result = await services.indexer.refresh(body.courseId ?? 'full', { force: body.force === true });
const scope = body.courseId ?? 'full';
// `wait: false` answers at once and leaves the caller to poll /status.
// Waiting for the result in this request is kept for older clients, but
// it cannot outlast a long crawl: Node's fetch abandons a response whose
// headers have not arrived within five minutes.
if (body.wait === false) {
const { run, joined } = services.indexer.start(scope, { force: body.force === true });
// The outcome is recorded by the indexer (status().lastResult/lastError);
// this only keeps an unawaited failure from becoming an unhandled one.
run.catch(() => {});
const status = services.indexer.status();
return res.status(202).json({ started: !joined, joined, scope, startedAt: status.startedAt ?? null });
}
const result = await services.indexer.refresh(scope, { force: body.force === true });
return res.json(result);
} catch (error) {
// A rate-limit refusal is the caller's problem to act on, not a fault.

View File

@@ -1,7 +1,7 @@
import { mkdir, stat, writeFile } from 'node:fs/promises';
import { dirname } from 'node:path';
import type { Config } from '../config.ts';
import type { SchulcloudClient } from '../core/client.ts';
import type { DownloadedFile, SchulcloudClient } from '../core/client.ts';
import { crawl, forEachLimited, type Snapshot } from '../core/crawl.ts';
import { extractContent, formatBytes } from '../core/extract.ts';
import { mirrorPath, resolveWithin } from '../core/paths.ts';
@@ -81,16 +81,30 @@ export class Indexer {
* while a run is in progress join it rather than starting a second.
*/
async refresh(scope: string, options: { force?: boolean } = {}): Promise<IndexResult> {
return this.start(scope, options).run;
}
/**
* Starts (or joins) a re-crawl without waiting for it.
*
* Not async on purpose: the rate-limit refusal throws synchronously, so a
* caller that answers immediately — the CLI's refresh route — can still
* report it. Waiting is the caller's choice, and holding one request open for
* a whole crawl does not survive a first crawl of the file manager: it
* downloads every course file once, and Node's fetch gives up on a response
* whose headers have not arrived after five minutes.
*/
start(scope: string, options: { force?: boolean } = {}): { run: Promise<IndexResult>; joined: boolean } {
// A full crawl covers every course, so a per-course request can ride along.
const existing = this.inFlight.get('full') ?? this.inFlight.get(scope);
if (existing) return existing.then((result) => ({ ...result, joined: true }));
if (existing) return { run: existing.then((result) => ({ ...result, joined: true })), joined: true };
const since = Date.now() - (this.lastFinishedAt.get(scope) ?? 0);
if (!options.force && since < this.minIntervalMs) {
const wait = Math.ceil((this.minIntervalMs - since) / 1000);
throw new Error(
`${scope === 'full' ? 'A full re-crawl' : `Course ${scope}`} was refreshed ${Math.round(since / 1000)}s ago. ` +
`Wait ${wait}s, or pass force to override — a full crawl is ~270 requests against Schulcloud.`,
`Wait ${wait}s, or pass force to override — a full crawl is several hundred requests against Schulcloud.`,
);
}
@@ -103,7 +117,7 @@ export class Indexer {
this.inFlight.set(scope, run);
this.runningScope = scope;
this.startedAt = new Date();
return run;
return { run, joined: false };
}
private async run(scope: string): Promise<IndexResult> {
@@ -192,12 +206,29 @@ export class Indexer {
return;
}
// Downloading and extracting fail for different reasons, and only the
// first is worth trying again: a timeout or a 503 is the network's, a
// PDF the parser rejects will reject again. Recording both the same way
// used to make every transient failure permanent.
let downloaded: DownloadedFile;
try {
// The file manager's ids mean nothing to files-storage; route by store.
const downloaded =
downloaded =
file.source === 'file-manager'
? await this.client.downloadFileManagerFile(file.record.id, file.record.name)
: await this.client.downloadFile(file.record);
} catch (error) {
await this.store.recordFileText({
fileId: entry.fileId, name: entry.name, mimeType: entry.mimeType, size: entry.size,
content: null,
note: `download failed, retried on the next crawl: ${error instanceof Error ? error.message : String(error)}`,
mirrorPath: null, mirrorSize: null, retry: true,
});
skipped++;
return;
}
try {
const relative = paths.get(entry.fileId);
if (!relative) return;
const absolute = resolveWithin(this.config.mirrorDir, relative);
@@ -223,7 +254,7 @@ export class Indexer {
await this.store.recordFileText({
fileId: entry.fileId, name: entry.name, mimeType: entry.mimeType, size: entry.size,
content: null,
note: `download or extraction failed: ${error instanceof Error ? error.message : String(error)}`,
note: `extraction failed: ${error instanceof Error ? error.message : String(error)}`,
mirrorPath: null, mirrorSize: null,
});
skipped++;

View File

@@ -6,6 +6,9 @@ import { failure, text, toToolError } from './result.ts';
const READ_ONLY = { readOnlyHint: true, destructiveHint: false, idempotentHint: true, openWorldHint: true };
/** How long refresh_index waits for a crawl before answering that it is still running. */
const REFRESH_WAIT_MS = 50_000;
export function registerIndexTools(server: McpServer, context: ServerContext): void {
server.registerTool(
'refresh_index',
@@ -14,8 +17,10 @@ export function registerIndexTools(server: McpServer, context: ServerContext): v
description:
'Re-reads Schulcloud and updates the local index, so search and what_changed see the newest state. ' +
'Pass a courseId when you know which course changed — that costs a handful of requests, whereas a ' +
'full re-crawl reads every course and takes up to a minute. Use it when the user says they just ' +
'uploaded or were given something and search cannot find it yet.',
'full re-crawl reads every course, every course\'s file-manager folders and every new file, and takes ' +
'minutes. A crawl that outlasts about 50 seconds keeps running in the background: this returns, and ' +
'index_status says when it is done. Use it when the user says they just uploaded or were given ' +
'something and search cannot find it yet.',
inputSchema: {
courseId: z
.string()
@@ -33,7 +38,27 @@ export function registerIndexTools(server: McpServer, context: ServerContext): v
async ({ courseId, force }) => {
if (!context.indexer) return failure(indexUnavailable('refresh_index'));
try {
const result = await context.indexer.refresh(courseId ?? 'full', { force });
const { run } = context.indexer.start(courseId ?? 'full', { force });
// A tool call must not wait out a long crawl: MCP clients time calls
// out, and a first crawl that downloads every course file runs for many
// minutes. The crawl carries on either way; the indexer records the
// outcome for index_status.
const outcome = await Promise.race([
run.then((result) => ({ done: true as const, result })),
new Promise<{ done: false }>((resolve) => setTimeout(() => resolve({ done: false }), REFRESH_WAIT_MS)),
]);
if (!outcome.done) {
run.catch(() => {});
return text(
joinSections([
heading(2, 'Re-crawl running in the background'),
`Still crawling ${courseId ? `course ${courseId}` : 'all courses'} after ${REFRESH_WAIT_MS / 1000}s. ` +
'It continues on the server; call index_status in a minute or two to see when it has finished. ' +
'Until then, search answers from the previous crawl.',
]),
);
}
const result = outcome.result;
return text(
joinSections([
heading(2, result.joined ? 'Joined a re-crawl already in progress' : 'Re-crawl complete'),
@@ -154,7 +179,14 @@ export function registerIndexTools(server: McpServer, context: ServerContext): v
const stats = await context.store.stats();
const status = context.indexer?.status();
if (stats.crawlId === undefined) {
return text('The index is empty. Run refresh_index to populate it.');
// The first crawl is the long one; "run refresh_index" while it is
// already running would only send the caller round in a circle.
return text(
status?.running
? `The first crawl is running now (started ${formatDate(status.startedAt)}). The index fills when ` +
'it finishes; the fs_* tools and the live tools work in the meantime.'
: 'The index is empty. Run refresh_index to populate it.',
);
}
const age = stats.crawledAt ? Date.now() - new Date(stats.crawledAt).getTime() : undefined;
return text(

View File

@@ -347,7 +347,14 @@ export class Store {
const { rows } = await this.db.query<{ node_id: string; title: string; meta: Record<string, unknown> }>(
`SELECT n.node_id, n.title, n.meta FROM nodes n
WHERE n.crawl_id = $1 AND n.kind = 'file'
AND NOT EXISTS (SELECT 1 FROM file_texts f WHERE f.file_id = n.node_id AND f.extracted_at IS NOT NULL)`,
AND NOT EXISTS (
SELECT 1 FROM file_texts f
WHERE f.file_id = n.node_id AND f.extracted_at IS NOT NULL
-- Recorded before transient and permanent failures were told
-- apart, under one note; each gets one more attempt, after which
-- it is re-recorded under the right kind.
AND coalesce(f.extract_note, '') NOT LIKE 'download or extraction failed%'
)`,
[crawlId],
);
return rows.map((row) => ({
@@ -367,24 +374,34 @@ export class Store {
note: string;
mirrorPath: string | null;
mirrorSize: number | null;
/** A transient failure: leave the file queued so the next crawl tries again. */
retry?: boolean;
}): Promise<void> {
// Postgres text cannot hold NUL, and PDF text extraction produces it: two
// live worksheets failed to store with "invalid byte sequence for encoding
// UTF8: 0x00" and were unsearchable. Stripped here, at the boundary, so no
// extractor can reintroduce it.
const content = entry.content === null ? null : stripNul(entry.content);
const note = stripNul(entry.note);
await this.db.query(
`INSERT INTO file_texts (file_id, name, mime_type, size, content, extract_note, extracted_at, mirror_path, mirror_size, mirrored_at)
VALUES ($1,$2,$3,$4,$5,$6, now(), $7,$8, CASE WHEN $7::text IS NULL THEN NULL ELSE now() END)
VALUES ($1,$2,$3,$4,$5,$6, CASE WHEN $9::boolean THEN NULL ELSE now() END, $7,$8, CASE WHEN $7::text IS NULL THEN NULL ELSE now() END)
ON CONFLICT (file_id) DO UPDATE SET
content = EXCLUDED.content, extract_note = EXCLUDED.extract_note, extracted_at = now(),
content = EXCLUDED.content, extract_note = EXCLUDED.extract_note,
extracted_at = CASE WHEN $9::boolean THEN NULL ELSE now() END,
mirror_path = COALESCE(EXCLUDED.mirror_path, file_texts.mirror_path),
mirror_size = COALESCE(EXCLUDED.mirror_size, file_texts.mirror_size),
mirrored_at = CASE WHEN EXCLUDED.mirror_path IS NULL THEN file_texts.mirrored_at ELSE now() END`,
[
entry.fileId,
entry.name,
stripNul(entry.name),
entry.mimeType,
entry.size,
entry.content,
entry.note,
content,
note,
entry.mirrorPath,
entry.mirrorSize,
entry.retry === true,
],
);
// Make the newly extracted text searchable in the current generation.
@@ -392,7 +409,7 @@ export class Store {
`UPDATE search_docs SET body = $2
WHERE kind = 'file' AND node_id = $1
AND crawl_id = (SELECT id FROM crawls WHERE status = 'ok' ORDER BY id DESC LIMIT 1)`,
[entry.fileId, entry.content ?? ''],
[entry.fileId, content ?? ''],
);
}
@@ -713,3 +730,7 @@ async function insertSearchDocs(
[crawlId],
);
}
function stripNul(value: string): string {
return value.includes('\u0000') ? value.replaceAll('\u0000', '') : value;
}

View File

@@ -109,3 +109,61 @@ describe('getCards chunking', () => {
assert.equal(cards.length, 2, 'one card from each of the two chunks');
});
});
describe('download timeouts', () => {
/**
* A real local server, because the timing is the point: a stubbed fetch
* cannot model bytes that keep arriving slowly. requestTimeoutMs is 1000ms.
*/
async function withServer(
handler: (res: import('node:http').ServerResponse) => void,
run: (base: string) => Promise<void>,
) {
const { createServer } = await import('node:http');
const server = createServer((_req, res) => handler(res));
await new Promise<void>((resolve) => server.listen(0, '127.0.0.1', resolve));
const { port } = server.address() as import('node:net').AddressInfo;
try {
await run(`http://127.0.0.1:${port}`);
} finally {
server.closeAllConnections();
await new Promise<void>((resolve) => server.close(() => resolve()));
}
}
const slowButSteady = (res: import('node:http').ServerResponse) => {
res.writeHead(200, { 'content-type': 'application/pdf' });
let sent = 0;
const tick = setInterval(() => {
res.write(Buffer.alloc(10, 65));
if (++sent === 4) {
clearInterval(tick);
res.end();
}
}, 400);
};
it('lets a download run past the request timeout while bytes keep arriving', async () => {
await withServer(slowButSteady, async (base) => {
// 4 chunks, 400ms apart: 1.6s in total against a 1s timeout, never 1s of silence.
const client = new SchulcloudClient({ ...config, baseUrl: base } as never);
const file = await client.getBytes('/file', 'slow.pdf');
assert.equal(file.bytes.length, 40);
assert.equal(file.truncated, false);
});
});
it('abandons a download that stalls', async () => {
await withServer(
(res) => {
res.writeHead(200, { 'content-type': 'application/pdf' });
res.write(Buffer.alloc(10, 65));
// …and then nothing, well past the 1s idle limit.
},
async (base) => {
const client = new SchulcloudClient({ ...config, baseUrl: base } as never);
await assert.rejects(client.getBytes('/file', 'stalled.pdf'), /no data received for 1s/);
},
);
});
});

View File

@@ -184,6 +184,30 @@ describe('Store', { skip: DB_URL ? false : 'set TEST_DATABASE_URL to run' }, ()
assert.ok(hits.some((h) => h.nodeId === 'f9'), 'PDF contents should be searchable, not just the filename');
});
it('stores extracted text containing NUL, which Postgres text refuses', async () => {
await store.recordFileText({
fileId: 'f9', name: 'skript.pdf', mimeType: 'application/pdf', size: 99,
content: 'Webserver\u0000 und Proxy', note: 'ok\u0000', mirrorPath: 'Info/Board/skript.pdf', mirrorSize: 99,
});
const hits = await store.search('Proxy');
assert.ok(hits.some((h) => h.nodeId === 'f9'), 'text with NUL bytes should still be stored and searchable');
});
it('keeps a file whose download failed queued for the next crawl, but not one that failed to extract', async () => {
await store.recordFileText({
fileId: 'f9', name: 'skript.pdf', mimeType: 'application/pdf', size: 99,
content: null, note: 'download failed, retried on the next crawl: timeout',
mirrorPath: null, mirrorSize: null, retry: true,
});
assert.ok((await store.filesNeedingText()).some((f) => f.fileId === 'f9'), 'a transient failure must be retried');
await store.recordFileText({
fileId: 'f9', name: 'skript.pdf', mimeType: 'application/pdf', size: 99,
content: null, note: 'extraction failed: bad xref', mirrorPath: null, mirrorSize: null,
});
assert.ok(!(await store.filesNeedingText()).some((f) => f.fileId === 'f9'), 'a parser failure is final');
});
it('resolves a timestamp cursor to a generation', async () => {
const id = await store.resolveCursor(new Date().toISOString());
assert.ok(id && id > 0);