From 4a17a1e713c6c49b6f2a6ef2958ac7016fe82e36 Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Fri, 11 Apr 2025 11:12:18 +0100 Subject: [PATCH] [web] gracefully access compile stats for event (#24818) * [web] gracefully access compile stats for event * [clsi] always emit stats and timings GitOrigin-RevId: 959e5fe1508245ffecfab1219fd86e53b210fca1 --- services/clsi/app/js/CompileController.js | 217 +++++++++--------- services/clsi/app/js/CompileManager.js | 10 +- .../acceptance/js/BrokenLatexFileTests.js | 9 + .../clsi/test/acceptance/js/TimeoutTests.js | 5 + .../test/unit/js/CompileControllerTests.js | 161 +++++++------ .../clsi/test/unit/js/CompileManagerTests.js | 28 ++- .../src/Features/Compile/CompileController.js | 4 +- 7 files changed, 244 insertions(+), 190 deletions(-) diff --git a/services/clsi/app/js/CompileController.js b/services/clsi/app/js/CompileController.js index 0075e3fe4a..20cac73c7a 100644 --- a/services/clsi/app/js/CompileController.js +++ b/services/clsi/app/js/CompileController.js @@ -30,115 +30,124 @@ function compile(req, res, next) { if (error) { return next(error) } - CompileManager.doCompileWithLock(request, (error, result) => { - let { buildId, outputFiles, stats, timings } = result || {} - let code, status - if (outputFiles == null) { - outputFiles = [] - } - if (error instanceof Errors.AlreadyCompilingError) { - code = 423 // Http 423 Locked - status = 'compile-in-progress' - } else if (error instanceof Errors.FilesOutOfSyncError) { - code = 409 // Http 409 Conflict - status = 'retry' - logger.warn( - { + const stats = {} + const timings = {} + CompileManager.doCompileWithLock( + request, + stats, + timings, + (error, result) => { + let { buildId, outputFiles } = result || {} + let code, status + if (outputFiles == null) { + outputFiles = [] + } + if (error instanceof Errors.AlreadyCompilingError) { + code = 423 // Http 423 Locked + status = 'compile-in-progress' + } else if (error instanceof Errors.FilesOutOfSyncError) { + code = 409 // Http 409 Conflict + status = 'retry' + logger.warn( + { + projectId: request.project_id, + userId: request.user_id, + }, + 'files out of sync, please retry' + ) + } else if ( + error?.code === 'EPIPE' || + error instanceof Errors.TooManyCompileRequestsError + ) { + // docker returns EPIPE when shutting down + code = 503 // send 503 Unavailable response + status = 'unavailable' + } else if (error?.terminated) { + status = 'terminated' + } else if (error?.validate) { + status = `validation-${error.validate}` + } else if (error?.timedout) { + status = 'timedout' + logger.debug( + { err: error, projectId: request.project_id }, + 'timeout running compile' + ) + } else if (error) { + status = 'error' + code = 500 + logger.error( + { err: error, projectId: request.project_id }, + 'error running compile' + ) + } else { + if ( + outputFiles.some( + file => file.path === 'output.pdf' && file.size > 0 + ) + ) { + status = 'success' + lastSuccessfulCompileTimestamp = Date.now() + } else if (request.stopOnFirstError) { + status = 'stopped-on-first-error' + } else { + status = 'failure' + logger.warn( + { projectId: request.project_id, outputFiles }, + 'project failed to compile successfully, no output.pdf generated' + ) + } + + // log an error if any core files are found + if (outputFiles.some(file => file.path === 'core')) { + logger.error( + { projectId: request.project_id, req, outputFiles }, + 'core file found in output' + ) + } + } + + if (error) { + outputFiles = error.outputFiles || [] + buildId = error.buildId + } + + if ( + status === 'success' && + request.editorId && + request.populateClsiCache + ) { + notifyCLSICacheAboutBuild({ projectId: request.project_id, userId: request.user_id, + buildId: outputFiles[0].build, + editorId: request.editorId, + outputFiles, + compileGroup: request.compileGroup, + }) + } + + timer.done() + res.status(code || 200).send({ + compile: { + status, + error: error?.message || error, + stats, + timings, + buildId, + outputUrlPrefix: Settings.apis.clsi.outputUrlPrefix, + outputFiles: outputFiles.map(file => ({ + url: + `${Settings.apis.clsi.url}/project/${request.project_id}` + + (request.user_id != null + ? `/user/${request.user_id}` + : '') + + `/build/${file.build}/output/${file.path}`, + ...file, + })), }, - 'files out of sync, please retry' - ) - } else if ( - error?.code === 'EPIPE' || - error instanceof Errors.TooManyCompileRequestsError - ) { - // docker returns EPIPE when shutting down - code = 503 // send 503 Unavailable response - status = 'unavailable' - } else if (error?.terminated) { - status = 'terminated' - } else if (error?.validate) { - status = `validation-${error.validate}` - } else if (error?.timedout) { - status = 'timedout' - logger.debug( - { err: error, projectId: request.project_id }, - 'timeout running compile' - ) - } else if (error) { - status = 'error' - code = 500 - logger.error( - { err: error, projectId: request.project_id }, - 'error running compile' - ) - } else { - if ( - outputFiles.some( - file => file.path === 'output.pdf' && file.size > 0 - ) - ) { - status = 'success' - lastSuccessfulCompileTimestamp = Date.now() - } else if (request.stopOnFirstError) { - status = 'stopped-on-first-error' - } else { - status = 'failure' - logger.warn( - { projectId: request.project_id, outputFiles }, - 'project failed to compile successfully, no output.pdf generated' - ) - } - - // log an error if any core files are found - if (outputFiles.some(file => file.path === 'core')) { - logger.error( - { projectId: request.project_id, req, outputFiles }, - 'core file found in output' - ) - } - } - - if (error) { - outputFiles = error.outputFiles || [] - buildId = error.buildId - } - - if ( - status === 'success' && - request.editorId && - request.populateClsiCache - ) { - notifyCLSICacheAboutBuild({ - projectId: request.project_id, - userId: request.user_id, - buildId: outputFiles[0].build, - editorId: request.editorId, - outputFiles, - compileGroup: request.compileGroup, }) } - - timer.done() - res.status(code || 200).send({ - compile: { - status, - error: error?.message || error, - stats, - timings, - buildId, - outputUrlPrefix: Settings.apis.clsi.outputUrlPrefix, - outputFiles: outputFiles.map(file => ({ - url: - `${Settings.apis.clsi.url}/project/${request.project_id}` + - (request.user_id != null ? `/user/${request.user_id}` : '') + - `/build/${file.build}/output/${file.path}`, - ...file, - })), - }, - }) - }) + ) } ) }) diff --git a/services/clsi/app/js/CompileManager.js b/services/clsi/app/js/CompileManager.js index b256195c9b..b65fb3cd02 100644 --- a/services/clsi/app/js/CompileManager.js +++ b/services/clsi/app/js/CompileManager.js @@ -46,24 +46,22 @@ function getOutputDir(projectId, userId) { return Path.join(Settings.path.outputDir, getCompileName(projectId, userId)) } -async function doCompileWithLock(request) { +async function doCompileWithLock(request, stats, timings) { const compileDir = getCompileDir(request.project_id, request.user_id) request.isInitialCompile = (await fsPromises.mkdir(compileDir, { recursive: true })) === compileDir // prevent simultaneous compiles const lock = LockManager.acquire(compileDir) try { - return await doCompile(request) + return await doCompile(request, stats, timings) } finally { lock.release() } } -async function doCompile(request) { +async function doCompile(request, stats, timings) { const { project_id: projectId, user_id: userId } = request const compileDir = getCompileDir(request.project_id, request.user_id) - const stats = {} - const timings = {} const timerE2E = new Metrics.Timer( 'compile-e2e-v2', @@ -321,7 +319,7 @@ async function doCompile(request) { emitPdfStats(stats, timings, request) } - return { outputFiles, stats, timings, buildId } + return { outputFiles, buildId } } async function _saveOutputFiles({ diff --git a/services/clsi/test/acceptance/js/BrokenLatexFileTests.js b/services/clsi/test/acceptance/js/BrokenLatexFileTests.js index d22c142cff..46d07da092 100644 --- a/services/clsi/test/acceptance/js/BrokenLatexFileTests.js +++ b/services/clsi/test/acceptance/js/BrokenLatexFileTests.js @@ -11,6 +11,7 @@ const Client = require('./helpers/Client') const request = require('request') const ClsiApp = require('./helpers/ClsiApp') +const { expect } = require('chai') describe('Broken LaTeX file', function () { before(function (done) { @@ -62,6 +63,10 @@ Hello world return this.body.compile.status.should.equal('failure') }) + it('should return isInitialCompile flag', function () { + expect(this.body.compile.stats.isInitialCompile).to.equal(1) + }) + it('should return output files', function () { // NOTE: No output.pdf file. this.body.compile.outputFiles @@ -98,6 +103,10 @@ Hello world return this.body.compile.status.should.equal('failure') }) + it('should not return isInitialCompile flag', function () { + expect(this.body.compile.stats.isInitialCompile).to.not.exist + }) + it('should return output files', function () { // NOTE: No output.pdf file. this.body.compile.outputFiles diff --git a/services/clsi/test/acceptance/js/TimeoutTests.js b/services/clsi/test/acceptance/js/TimeoutTests.js index bca8ae71d2..e9175d223c 100644 --- a/services/clsi/test/acceptance/js/TimeoutTests.js +++ b/services/clsi/test/acceptance/js/TimeoutTests.js @@ -11,6 +11,7 @@ const Client = require('./helpers/Client') const request = require('request') const ClsiApp = require('./helpers/ClsiApp') +const { expect } = require('chai') describe('Timed out compile', function () { before(function (done) { @@ -54,6 +55,10 @@ describe('Timed out compile', function () { return this.body.compile.status.should.equal('timedout') }) + it('should return isInitialCompile flag', function () { + expect(this.body.compile.stats.isInitialCompile).to.equal(1) + }) + return it('should return the log output file name', function () { const outputFilePaths = this.body.compile.outputFiles.map(x => x.path) return outputFilePaths.should.include('output.log') diff --git a/services/clsi/test/unit/js/CompileControllerTests.js b/services/clsi/test/unit/js/CompileControllerTests.js index 03cd9932e9..e6d21aed9f 100644 --- a/services/clsi/test/unit/js/CompileControllerTests.js +++ b/services/clsi/test/unit/js/CompileControllerTests.js @@ -80,16 +80,21 @@ describe('CompileController', function () { this.timings = { bar: 2 } this.res.status = sinon.stub().returnsThis() this.res.send = sinon.stub() + + this.CompileManager.doCompileWithLock = sinon + .stub() + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(null, { + outputFiles: this.output_files, + buildId: this.buildId, + }) + }) }) describe('successfully', function () { beforeEach(function () { - this.CompileManager.doCompileWithLock = sinon.stub().yields(null, { - outputFiles: this.output_files, - stats: this.stats, - timings: this.timings, - buildId: this.buildId, - }) this.CompileController.compile(this.req, this.res) }) @@ -133,12 +138,6 @@ describe('CompileController', function () { describe('without a outputUrlPrefix', function () { beforeEach(function () { this.Settings.apis.clsi.outputUrlPrefix = '' - this.CompileManager.doCompileWithLock = sinon.stub().yields(null, { - outputFiles: this.output_files, - stats: this.stats, - timings: this.timings, - buildId: this.buildId, - }) this.CompileController.compile(this.req, this.res) }) @@ -177,33 +176,35 @@ describe('CompileController', function () { build: 1234, }, ] - this.CompileManager.doCompileWithLock = sinon.stub().yields(null, { - outputFiles: this.output_files, - stats: this.stats, - timings: this.timings, - buildId: this.buildId, - }) + this.CompileManager.doCompileWithLock = sinon + .stub() + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(null, { + outputFiles: this.output_files, + buildId: this.buildId, + }) + }) this.CompileController.compile(this.req, this.res) }) it('should return the JSON response with status failure', function () { this.res.status.calledWith(200).should.equal(true) - this.res.send - .calledWith({ - compile: { - status: 'failure', - error: null, - stats: this.stats, - timings: this.timings, - outputUrlPrefix: '/zone/b', - buildId: this.buildId, - outputFiles: this.output_files.map(file => ({ - url: `${this.Settings.apis.clsi.url}/project/${this.project_id}/build/${file.build}/output/${file.path}`, - ...file, - })), - }, - }) - .should.equal(true) + this.res.send.should.have.been.calledWith({ + compile: { + status: 'failure', + error: null, + stats: this.stats, + timings: this.timings, + outputUrlPrefix: '/zone/b', + buildId: this.buildId, + outputFiles: this.output_files.map(file => ({ + url: `${this.Settings.apis.clsi.url}/project/${this.project_id}/build/${file.build}/output/${file.path}`, + ...file, + })), + }, + }) }) }) @@ -222,33 +223,35 @@ describe('CompileController', function () { build: 1234, }, ] - this.CompileManager.doCompileWithLock = sinon.stub().yields(null, { - outputFiles: this.output_files, - stats: this.stats, - timings: this.timings, - buildId: this.buildId, - }) + this.CompileManager.doCompileWithLock = sinon + .stub() + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(null, { + outputFiles: this.output_files, + buildId: this.buildId, + }) + }) this.CompileController.compile(this.req, this.res) }) it('should return the JSON response with status failure', function () { this.res.status.calledWith(200).should.equal(true) - this.res.send - .calledWith({ - compile: { - status: 'failure', - error: null, - stats: this.stats, - buildId: this.buildId, - timings: this.timings, - outputUrlPrefix: '/zone/b', - outputFiles: this.output_files.map(file => ({ - url: `${this.Settings.apis.clsi.url}/project/${this.project_id}/build/${file.build}/output/${file.path}`, - ...file, - })), - }, - }) - .should.equal(true) + this.res.send.should.have.been.calledWith({ + compile: { + status: 'failure', + error: null, + stats: this.stats, + buildId: this.buildId, + timings: this.timings, + outputUrlPrefix: '/zone/b', + outputFiles: this.output_files.map(file => ({ + url: `${this.Settings.apis.clsi.url}/project/${this.project_id}/build/${file.build}/output/${file.path}`, + ...file, + })), + }, + }) }) }) @@ -258,7 +261,11 @@ describe('CompileController', function () { error.buildId = this.buildId this.CompileManager.doCompileWithLock = sinon .stub() - .callsArgWith(1, error, null) + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(error) + }) this.CompileController.compile(this.req, this.res) }) @@ -272,9 +279,8 @@ describe('CompileController', function () { outputUrlPrefix: '/zone/b', outputFiles: [], buildId: this.buildId, - // JSON.stringify will omit these - stats: undefined, - timings: undefined, + stats: this.stats, + timings: this.timings, }, }) .should.equal(true) @@ -288,7 +294,11 @@ describe('CompileController', function () { ) this.CompileManager.doCompileWithLock = sinon .stub() - .callsArgWith(1, error, null) + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(error) + }) this.CompileController.compile(this.req, this.res) }) @@ -301,9 +311,10 @@ describe('CompileController', function () { error: 'too many concurrent compile requests', outputUrlPrefix: '/zone/b', outputFiles: [], + stats: this.stats, + timings: this.timings, + // JSON.stringify will omit these undefined values buildId: undefined, - stats: undefined, - timings: undefined, }, }) .should.equal(true) @@ -316,7 +327,11 @@ describe('CompileController', function () { this.error.timedout = true this.CompileManager.doCompileWithLock = sinon .stub() - .callsArgWith(1, this.error, null) + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(this.error) + }) this.CompileController.compile(this.req, this.res) }) @@ -329,10 +344,10 @@ describe('CompileController', function () { error: this.message, outputUrlPrefix: '/zone/b', outputFiles: [], - // JSON.stringify will omit these + stats: this.stats, + timings: this.timings, + // JSON.stringify will omit these undefined values buildId: undefined, - stats: undefined, - timings: undefined, }, }) .should.equal(true) @@ -343,7 +358,11 @@ describe('CompileController', function () { beforeEach(function () { this.CompileManager.doCompileWithLock = sinon .stub() - .callsArgWith(1, null, []) + .callsFake((_req, stats, timings, cb) => { + Object.assign(stats, this.stats) + Object.assign(timings, this.timings) + cb(null, {}) + }) this.CompileController.compile(this.req, this.res) }) @@ -356,10 +375,10 @@ describe('CompileController', function () { status: 'failure', outputUrlPrefix: '/zone/b', outputFiles: [], - // JSON.stringify will omit these + stats: this.stats, + timings: this.timings, + // JSON.stringify will omit these undefined values buildId: undefined, - stats: undefined, - timings: undefined, }, }) .should.equal(true) diff --git a/services/clsi/test/unit/js/CompileManagerTests.js b/services/clsi/test/unit/js/CompileManagerTests.js index 5fe28d27f9..33a43ae029 100644 --- a/services/clsi/test/unit/js/CompileManagerTests.js +++ b/services/clsi/test/unit/js/CompileManagerTests.js @@ -199,7 +199,7 @@ describe('CompileManager', function () { const error = new Error('locked') this.LockManager.acquire.throws(error) await expect( - this.CompileManager.promises.doCompileWithLock(this.request) + this.CompileManager.promises.doCompileWithLock(this.request, {}, {}) ).to.be.rejectedWith(error) }) @@ -217,7 +217,9 @@ describe('CompileManager', function () { describe('normally', function () { beforeEach(async function () { this.result = await this.CompileManager.promises.doCompileWithLock( - this.request + this.request, + {}, + {} ) }) @@ -271,7 +273,11 @@ describe('CompileManager', function () { describe('with draft mode', function () { beforeEach(async function () { this.request.draft = true - await this.CompileManager.promises.doCompileWithLock(this.request) + await this.CompileManager.promises.doCompileWithLock( + this.request, + {}, + {} + ) }) it('should inject the draft mode header', function () { @@ -284,7 +290,11 @@ describe('CompileManager', function () { describe('with a check option', function () { beforeEach(async function () { this.request.check = 'error' - await this.CompileManager.promises.doCompileWithLock(this.request) + await this.CompileManager.promises.doCompileWithLock( + this.request, + {}, + {} + ) }) it('should run chktex', function () { @@ -316,7 +326,11 @@ describe('CompileManager', function () { beforeEach(async function () { this.request.rootResourcePath = 'main.Rtex' this.request.check = 'error' - await this.CompileManager.promises.doCompileWithLock(this.request) + await this.CompileManager.promises.doCompileWithLock( + this.request, + {}, + {} + ) }) it('should not run chktex', function () { @@ -345,7 +359,7 @@ describe('CompileManager', function () { error.timedout = true this.LatexRunner.promises.runLatex.rejects(error) await expect( - this.CompileManager.promises.doCompileWithLock(this.request) + this.CompileManager.promises.doCompileWithLock(this.request, {}, {}) ).to.be.rejected }) @@ -368,7 +382,7 @@ describe('CompileManager', function () { error.terminated = true this.LatexRunner.promises.runLatex.rejects(error) await expect( - this.CompileManager.promises.doCompileWithLock(this.request) + this.CompileManager.promises.doCompileWithLock(this.request, {}, {}) ).to.be.rejected }) diff --git a/services/web/app/src/Features/Compile/CompileController.js b/services/web/app/src/Features/Compile/CompileController.js index bb225c6b79..c981e93dcb 100644 --- a/services/web/app/src/Features/Compile/CompileController.js +++ b/services/web/app/src/Features/Compile/CompileController.js @@ -226,8 +226,8 @@ module.exports = CompileController = { timeout: limits.timeout === 60 ? 'short' : 'long', server: clsiServerId?.includes('-c2d-') ? 'faster' : 'normal', isAutoCompile, - isInitialCompile: stats.isInitialCompile === 1, - restoredClsiCache: stats.restoredClsiCache === 1, + isInitialCompile: stats?.isInitialCompile === 1, + restoredClsiCache: stats?.restoredClsiCache === 1, stopOnFirstError, } )