From 79fd96e1d38da927a9b4634f479541e081a87f42 Mon Sep 17 00:00:00 2001 From: David Poeschl Date: Sun, 17 Dec 2023 08:30:16 -0800 Subject: [PATCH] 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 | 200 +++++++++++++++++++---- sandbox/src/run/java.ts | 58 +++++-- web/src/routes/api/submission/+server.ts | 8 +- 3 files changed, 217 insertions(+), 49 deletions(-) diff --git a/sandbox/src/index.ts b/sandbox/src/index.ts index a35d865..3ec4564 100644 --- a/sandbox/src/index.ts +++ b/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 os from 'os'; +import { string, z } from 'zod'; +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; async function fetchQueuedSubmission(): Promise { - 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( - repoUrl, - submissionData.submission.contestId.toString(), - submissionData.submission.teamId.toString() + '.git' - ), + teamRepoUrl, '.' ); 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 { let submissionData: SubmissionGetData | undefined; try { submissionData = await fetchQueuedSubmission(); - } catch { - console.error('Failed to fetch submission'); - return; + } catch (e) { + console.error(`Failed to fetch from ${submissionApiUrl} with error: ${e}`); + return SubmissionProcessingResult.Error; } if (!submissionData) { console.error('Unable to fetch submission data'); - } else { - try { - cloneAndRun(submissionData); - } catch { - console.error('Unable to clone and run'); + return SubmissionProcessingResult.Error; + } + + if (!submissionData.submission) { + 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(); diff --git a/sandbox/src/run/java.ts b/sandbox/src/run/java.ts index 990aeda..137105a 100644 --- a/sandbox/src/run/java.ts +++ b/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 { +): Promise { + 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) { - resolved = true; - resolve(outputBuffer); + completedNormally = !timeLimitExceeded; + + 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(() => { - if (!resolved) { - console.log('30 seconds reached, killing process'); - resolved = true; - child.kill('SIGKILL'); - resolve(outputBuffer + '\n[Timeout after 30 seconds]'); + let timeoutHandle = setTimeout(() => { + if (completedNormally) { + return; } - }, 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); }); } diff --git a/web/src/routes/api/submission/+server.ts b/web/src/routes/api/submission/+server.ts index d52053c..93b2a24 100644 --- a/web/src/routes/api/submission/+server.ts +++ b/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, - teamId: submissions[0].teamId, + contestId: submissions[0].contest.id, + 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,