Sandbox: Ensure runs are serialized, add detailed logging (#9)

Specific fixes to ensure runs are serialized:

- Added missing await when starting clone/run
- The runJava method now has a single exit path that can only execute when the process has guaranteed been 'close'd. The timeout detection previously sent SIGKILL and assumed it worked, but it was not working on my machine and the student code would continue to run indefinitely after returning.
- To get the SIGKILL to kill the submitted app's process, I added end/destroy calls to the process stdin/stdout/stderr streams.

Added lots of logging while diagnosing these issues, and it seems useful to keep. As part of this, the contest/team names are now included in the 'submissions' web api.

Also, I've structured the result data in more detail within the Sandbox, tracking whether a run succeeded or the way in which it failed. I'm collapsing these back down to just a string "output" with the preexisting failure markers (e.g. "[Timeout after 30 seconds]"), but would like to pass this over to the site/DB in a structured form eventually.

sandbox/src/index.ts

@@ -1,12 +1,14 @@
 import dotenv from 'dotenv';
 import fs from 'fs-extra';
 import urlJoin from 'url-join';
-import { z } from 'zod';
+import { string, z } from 'zod';
-import os from 'os';
+import os, { EOL } from 'os';
 import { join } from 'path';
 import { simpleGit, SimpleGit } from 'simple-git';
 import { runJava } from './run/java.js';
 
+export const timeoutSeconds = 30;
+
 const submissionGetData = z
 	.object({
 		success: z.boolean(),
@@ -14,7 +16,9 @@ const submissionGetData = z
 			.object({
 				id: z.number(),
 				contestId: z.number(),
+				contestName: z.string(),
 				teamId: z.number(),
+				teamName: z.string(),
 				problem: z.object({
 					id: z.number(),
 					pascalName: z.string(),
@@ -26,14 +30,37 @@ const submissionGetData = z
 	})
 	.strict();
 
+export type RunResult = {
+	kind: RunResultKind,
+	teamOutput?: string,
+	exitCode?: number,
+	runtimeMilliseconds?: number
+	buildErrors?: string,
+	sandboxErrorText?: string,
+}
+
+export enum RunResultKind {
+	CompileFailed,
+	TimeLimitExceeded,
+	Completed,
+	SandboxError
+}
+
+enum SubmissionProcessingResult {
+	NoSubmissions,
+	SubmissionProcessed,
+	Error
+}
+
 type SubmissionGetData = z.infer<typeof submissionGetData>;
 
 async function fetchQueuedSubmission(): Promise<SubmissionGetData | undefined> {
-	const res = await fetch(urlJoin(adminUrl, 'api/submission'), { method: 'GET' });
+	const res = await fetch(submissionApiUrl, { method: 'GET' });
 	if (res.status !== 200) {
-		console.error('Failed to fetch submission');
+		console.error(`Failed to fetch from ${submissionApiUrl} with status: ${res.status} ${res.statusText}`);
 		return undefined;
 	}
+
 	const data = submissionGetData.parse(await res.json());
 	if (!data.success) {
 		return undefined;
@@ -54,20 +81,24 @@ async function cloneAndRun(submissionData: SubmissionGetData) {
 	const repoDir = join(buildDir, 'src');
 	fs.mkdirSync(repoDir);
 
+	const teamRepoUrl = urlJoin(
+		repoUrl,
+		submissionData.submission.contestId.toString(),
+		submissionData.submission.teamId.toString() + '.git'
+	);
+
+	console.log(`- CLONE: from ${teamRepoUrl}`);
 	const git: SimpleGit = simpleGit({ baseDir: repoDir });
 	await git.clone(
-		urlJoin(
+		teamRepoUrl,
-			repoUrl,
-			submissionData.submission.contestId.toString(),
-			submissionData.submission.teamId.toString() + '.git'
-		),
 		'.'
 	);
 	await git.checkout(submissionData.submission.commitHash);
 	const problemName = submissionData.submission.problem.pascalName;
-	let output: string;
+	let runResult: RunResult;
+
 	try {
-		output = await runJava(
+		runResult = await runJava(
 			javaBinPath,
 			buildDir,
 			join(repoDir, problemName, problemName + '.java'),
@@ -75,21 +106,70 @@ async function cloneAndRun(submissionData: SubmissionGetData) {
 			submissionData.submission.problem.realInput
 		);
 	} catch (error) {
-		output = `[An error occurred while running]\n${error}`;
+		runResult = {
+			kind: RunResultKind.SandboxError, 
+			sandboxErrorText: `An unexpected error occurred: ${EOL} ${error}`};
 	}
 
+	printRunResult(runResult);
+
 	const res = await fetch(urlJoin(adminUrl, 'api/submission'), {
 		method: 'POST',
 		headers: { 'Content-Type': 'application/json' },
-		body: JSON.stringify({ submissionId: submissionData.submission.id, output: output })
+		body: JSON.stringify(makePostBody(submissionData.submission.id, runResult))
 	});
 	if (res.status !== 200) {
-		console.error('Failed to POST output');
+		console.error('- POST: Failed with error code: ' + res.status + " " + res.statusText);
+		return;
 	}
+
 	const data = (await res.json()) as { success: boolean };
 	if (!data.success) {
-		console.error('Output POST unsuccessful');
+		console.error('- POST: Failed with response: ' + JSON.stringify(data));
+		return;
 	}
+
+	console.log(`- POST: Succeeded`);
+}
+
+function printRunResult(runResult: RunResult) {
+	console.log(`- RESULT: ${getRunResultDisplayText()}`);
+
+	function getRunResultDisplayText() {
+		if (runResult.kind == RunResultKind.SandboxError) {
+			return "Sandbox error: " + runResult.sandboxErrorText;
+		}
+
+		if (runResult.kind == RunResultKind.CompileFailed) {
+			return "Failed to compile";
+		}
+
+		if (runResult.kind == RunResultKind.TimeLimitExceeded) {
+			return `Time limit exceeded. Output Length: ${runResult.teamOutput?.length}.`;
+		}
+
+		return `Run completed. Time: ${runResult.runtimeMilliseconds}ms. Output Length: ${runResult.teamOutput?.length}. Exit Code: ${runResult.exitCode}`;
+	}
+}
+
+function makePostBody(submissionId: number, runResult: RunResult): { submissionId: number, output: string } {
+	let output: string;
+	switch (runResult.kind) {
+		case RunResultKind.CompileFailed:
+			output = `[Build Errors] ${EOL} ${runResult.buildErrors}`;
+			break;
+		case RunResultKind.TimeLimitExceeded:
+			output = `${runResult.teamOutput} ${EOL} [Timeout after ${timeoutSeconds} seconds]`;
+			break;
+		case RunResultKind.Completed:
+			output = runResult.teamOutput!;
+			break;
+		case RunResultKind.SandboxError:
+			output = `[Sandbox Error] ${EOL} ${runResult.sandboxErrorText}`;
+			break;
+	}
+
+	return { submissionId, output }
 }
 
 function validateEnv(): boolean {
@@ -110,31 +190,89 @@ const adminUrl = process.env.ADMIN_URL as string;
 const repoUrl = process.env.REPO_URL as string;
 const javaBinPath = process.env.JAVA_PATH as string;
 
-async function loop() {
+const submissionApiUrl = urlJoin(adminUrl, 'api/submission');
+
+async function processNextSubmission(): Promise<SubmissionProcessingResult> {
 	let submissionData: SubmissionGetData | undefined;
 	try {
 		submissionData = await fetchQueuedSubmission();
-	} catch {
+	} catch (e) {
-		console.error('Failed to fetch submission');
+		console.error(`Failed to fetch from ${submissionApiUrl} with error: ${e}`);
-		return;
+		return SubmissionProcessingResult.Error;
 	}
 
 	if (!submissionData) {
 		console.error('Unable to fetch submission data');
-	} else {
+		return SubmissionProcessingResult.Error;
-		try {
+	}
-			cloneAndRun(submissionData);
+
-		} catch {
+	if (!submissionData.submission) {
-			console.error('Unable to clone and run');
+		return SubmissionProcessingResult.NoSubmissions;
+	}
+	
+	printSubmissionHeader(submissionData);
+
+	let processingResult: SubmissionProcessingResult;
+	try {
+		await cloneAndRun(submissionData);
+		processingResult = SubmissionProcessingResult.SubmissionProcessed;
+	} catch {
+		console.error('Failed to clone/run.');
+		processingResult = SubmissionProcessingResult.Error;
+	}
+
+	printSubmissionFooter(submissionData);
+	return processingResult;
+}
+
+function printSubmissionHeader(submissionData: SubmissionGetData) {
+	const submission = submissionData.submission;
+	if (!submission) {
+		return;
+	}
+
+	console.log(`--- Submission ${submission.id} ---`);
+	console.log(`- INFO: Contest ${submission.contestId} '${submission.contestName}', ` +
+		`Team ${submission.teamId} '${submission.teamName}', ` +
+		`Problem ${submission.problem.id} '${submission.problem.pascalName}', ` +
+		`SHA '${submission.commitHash}'`);
+}
+
+function printSubmissionFooter(submissionData: SubmissionGetData) {
+	const submission = submissionData.submission;
+	if (!submission) {
+		return;
+	}
+
+	console.log(`--- End Submission ${submission.id} ---`);
+}
+
+async function run() {
+	console.log("Sandbox started. Periodically checking for submissions.");
+
+	let iterationsSinceProcessedSubmission = 0;
+	let anySubmissionsProcessed = false;
+	while (true) {
+		switch (await processNextSubmission()) {
+			case SubmissionProcessingResult.SubmissionProcessed:
+				iterationsSinceProcessedSubmission = 0;
+				anySubmissionsProcessed = true;
+				break;
+			case SubmissionProcessingResult.NoSubmissions:
+				if (iterationsSinceProcessedSubmission > 0 && iterationsSinceProcessedSubmission % 6 == 0) {
+					const numMinutes = iterationsSinceProcessedSubmission / 6;
+					console.log(`${numMinutes} minute${(numMinutes > 1 ? 's' : '')} since ` +
+						`${(anySubmissionsProcessed ? `last submission processed` : `sandbox startup with no submissions`)}`);
+				}
+
+				await new Promise((resolve) => setTimeout(resolve, 10000));
+				iterationsSinceProcessedSubmission++;
+				break;
+			case SubmissionProcessingResult.Error:
+				await new Promise((resolve) => setTimeout(resolve, 10000));
+				break;
 		}
 	}
 }
 
-async function run() {
-	while (true) {
-		await loop();
-		await new Promise((resolve) => setTimeout(resolve, 10000));
-	}
-}
-
 run();

sandbox/src/run/java.ts

@@ -1,6 +1,7 @@
 import { join } from 'path';
 import { exec, spawn } from 'child_process';
 import util from 'util';
+import { RunResult, RunResultKind, timeoutSeconds } from '../index.js';
 
 const execPromise = util.promisify(exec);
 
@@ -10,15 +11,23 @@ export async function runJava(
 	mainFile: string,
 	mainClass: string,
 	input: string
-): Promise<string> {
+): Promise<RunResult> {
+	console.log(`- BUILD: ${mainFile}`);
 	const compileCommand = `${join(javaBinPath, 'javac')} -cp ${join(
 		buildDir,
 		'src'
 	)} ${mainFile} -d ${join(buildDir, 'build')}`;
-	await execPromise(compileCommand);
 
+	try {
+		await execPromise(compileCommand);
+	} catch(e) {
+		const buildErrorText = e?.toString() ?? "Unknown build errors.";
+		console.log("Build errors: " + buildErrorText);
+		return {kind: RunResultKind.CompileFailed, buildErrors: buildErrorText};
+	}
+
+	console.log(`- RUN: ${mainClass}`);
 	const runCommand = `${join(javaBinPath, 'java')} -cp "${join(buildDir, 'build')}" ${mainClass}`;
-
 	return new Promise((resolve) => {
 		let outputBuffer = '';
 		const child = spawn(runCommand, { shell: true });
@@ -30,25 +39,44 @@ export async function runJava(
 		child.stderr.on('data', (data) => {
 			outputBuffer += data.toString();
 		});
+
+		let runStartTime = performance.now();
 		child.stdin.write(input);
 		child.stdin.end();
 
-		let resolved = false;
+		let timeLimitExceeded = false;
-
+		let completedNormally = false;
+		
 		child.on('close', () => {
-			if (!resolved) {
+			completedNormally = !timeLimitExceeded;
-				resolved = true;
+
-				resolve(outputBuffer);
+			let runEndTime = performance.now();
+			const runtimeMilliseconds = Math.floor(runEndTime - runStartTime);
+
+			if (completedNormally) {
+				clearTimeout(timeoutHandle);
+				resolve({kind: RunResultKind.Completed, teamOutput: outputBuffer, 
+					exitCode: child.exitCode!, runtimeMilliseconds});
+			}
+			else {
+				console.log(`Process terminated, total sandbox time: ${runtimeMilliseconds}ms`);
+				resolve({kind: RunResultKind.TimeLimitExceeded, teamOutput: outputBuffer});
 			}
 		});
 
-		setTimeout(() => {
+		let timeoutHandle = setTimeout(() => {
-			if (!resolved) {
+			if (completedNormally) {
-				console.log('30 seconds reached, killing process');
+				return;
-				resolved = true;
-				child.kill('SIGKILL');
-				resolve(outputBuffer + '\n[Timeout after 30 seconds]');
 			}
-		}, 30000);
+
+			console.log(`Run timed out after ${timeoutSeconds} seconds, killing process...`);
+			timeLimitExceeded = true;
+
+			child.stdin.end();
+			child.stdin.destroy();
+			child.stdout.destroy();
+			child.stderr.destroy();
+			child.kill('SIGKILL');
+		}, timeoutSeconds * 1000);
 	});
 }

web/src/routes/api/submission/+server.ts

@@ -9,7 +9,7 @@ export const GET = (async () => {
 	const submissions = await db.submission.findMany({
 		where: { state: SubmissionState.Queued },
 		orderBy: { createdAt: 'asc' },
-		include: { problem: true },
+		include: { problem: true, contest: true, team: true },
 		take: 1
 	});
 	if (submissions.length !== 0) {
@@ -17,8 +17,10 @@ export const GET = (async () => {
 			success: true,
 			submission: {
 				id: submissions[0].id,
-				contestId: submissions[0].contestId,
+				contestId: submissions[0].contest.id,
-				teamId: submissions[0].teamId,
+				contestName: submissions[0].contest.name,
+				teamId: submissions[0].team.id,
+				teamName: submissions[0].team.name,
 				problem: {
 					id: submissions[0].problemId,
 					pascalName: submissions[0].problem.pascalName,