From 7ceadc859945cff40c18e711ec9d52c1adb99958 Mon Sep 17 00:00:00 2001 From: Tim Alby Date: Thu, 11 Jun 2020 12:50:43 +0200 Subject: [PATCH 1/6] partially revert "[DockerRunner] fix metric incrementing and error logging" This reverts commits: - 2b2fcca39ce8dee0fdc0c342aa0d6c822592bcec - 9e82ab0890c5cc8c7fb95362c3f7edbcaad0cf29 - e3da458b376871c3ce72d6984d14bf1ee668b04b --- app/js/DockerRunner.js | 36 +++++++------------ test/unit/js/DockerRunnerTests.js | 58 ------------------------------- 2 files changed, 13 insertions(+), 81 deletions(-) diff --git a/app/js/DockerRunner.js b/app/js/DockerRunner.js index c50087d..3f90c81 100644 --- a/app/js/DockerRunner.js +++ b/app/js/DockerRunner.js @@ -26,7 +26,6 @@ const LockManager = require('./DockerLockManager') const fs = require('fs') const Path = require('path') const _ = require('underscore') -const metrics = require('metrics-sharelatex') logger.info('using docker runner') @@ -412,28 +411,19 @@ module.exports = DockerRunner = { }) } ) - var inspectContainer = isRetry => - container.inspect(function(error, stats) { - if ((error != null ? error.statusCode : undefined) === 404) { - return createAndStartContainer() - } else if (error != null) { - if (error.message.match(/EPIPE/)) { - if (!isRetry) { - metrics.inc('container-inspect-epipe-retry') - return inspectContainer(true) - } - metrics.inc('container-inspect-epipe-error') - } - logger.err( - { container_name: name, error }, - 'unable to inspect container to start' - ) - return callback(error) - } else { - return startExistingContainer() - } - }) - inspectContainer(false) + return container.inspect(function(error, stats) { + if ((error != null ? error.statusCode : undefined) === 404) { + return createAndStartContainer() + } else if (error != null) { + logger.err( + { container_name: name, error }, + 'unable to inspect container to start' + ) + return callback(error) + } else { + return startExistingContainer() + } + }) }, attachToContainer(containerId, attachStreamHandler, attachStartCallback) { diff --git a/test/unit/js/DockerRunnerTests.js b/test/unit/js/DockerRunnerTests.js index 1e44daf..aa45e88 100644 --- a/test/unit/js/DockerRunnerTests.js +++ b/test/unit/js/DockerRunnerTests.js @@ -36,7 +36,6 @@ describe('DockerRunner', function() { 'logger-sharelatex': (this.logger = { log: sinon.stub(), error: sinon.stub(), - err: sinon.stub(), info: sinon.stub(), warn: sinon.stub() }), @@ -388,63 +387,6 @@ describe('DockerRunner', function() { }) }) - describe('when inspect always fails with EPIPE error', function() { - beforeEach(function() { - this.error = new Error('write EPIPE') - this.container.inspect = sinon.stub().yields(this.error) - this.container.start = sinon.stub().yields() - - this.DockerRunner.startContainer( - this.options, - this.volumes, - () => {}, - this.callback - ) - }) - - it('should retry once', function() { - sinon.assert.callOrder( - this.container.inspect, - this.container.inspect, - this.callback - ) - }) - - it('should call back with error', function() { - sinon.assert.calledWith(this.callback, this.error) - }) - }) - - describe('when inspect fails once with EPIPE error', function() { - beforeEach(function() { - this.container.inspect = sinon.stub() - this.container.inspect.onFirstCall().yields(new Error('write EPIPE')) - this.container.inspect.onSecondCall().yields() - this.container.start = sinon.stub().yields() - - this.DockerRunner.startContainer( - this.options, - this.volumes, - () => {}, - this.callback - ) - }) - - it('should retry once and start container', function() { - sinon.assert.callOrder( - this.container.inspect, - this.container.inspect, - this.DockerRunner.attachToContainer, - this.container.start, - this.callback - ) - }) - - it('should call back without error', function() { - sinon.assert.calledWith(this.callback, null) - }) - }) - describe('when the container does not exist', function() { beforeEach(function() { const exists = false From 33d6462875fe17aebb57d808736a2c1c58c329f0 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 12 Jun 2020 15:15:27 +0100 Subject: [PATCH 2/6] check output file exists before running synctex --- app/js/CompileManager.js | 119 ++++++++++++++++----------------------- 1 file changed, 49 insertions(+), 70 deletions(-) diff --git a/app/js/CompileManager.js b/app/js/CompileManager.js index 614c49a..4b0cff6 100644 --- a/app/js/CompileManager.js +++ b/app/js/CompileManager.js @@ -430,30 +430,18 @@ module.exports = CompileManager = { const compileDir = getCompileDir(project_id, user_id) const synctex_path = `${base_dir}/output.pdf` const command = ['code', synctex_path, file_path, line, column] - return fse.ensureDir(compileDir, function(error) { + CompileManager._runSynctex(project_id, user_id, command, function( + error, + stdout + ) { if (error != null) { - logger.err( - { error, project_id, user_id, file_name }, - 'error ensuring dir for sync from code' - ) return callback(error) } - return CompileManager._runSynctex(project_id, user_id, command, function( - error, - stdout - ) { - if (error != null) { - return callback(error) - } - logger.log( - { project_id, user_id, file_name, line, column, command, stdout }, - 'synctex code output' - ) - return callback( - null, - CompileManager._parseSynctexFromCodeOutput(stdout) - ) - }) + logger.log( + { project_id, user_id, file_name, line, column, command, stdout }, + 'synctex code output' + ) + return callback(null, CompileManager._parseSynctexFromCodeOutput(stdout)) }) }, @@ -466,53 +454,39 @@ module.exports = CompileManager = { const base_dir = Settings.path.synctexBaseDir(compileName) const synctex_path = `${base_dir}/output.pdf` const command = ['pdf', synctex_path, page, h, v] - return fse.ensureDir(compileDir, function(error) { + CompileManager._runSynctex(project_id, user_id, command, function( + error, + stdout + ) { if (error != null) { - logger.err( - { error, project_id, user_id, file_name }, - 'error ensuring dir for sync to code' - ) return callback(error) } - return CompileManager._runSynctex(project_id, user_id, command, function( - error, - stdout - ) { - if (error != null) { - return callback(error) - } - logger.log( - { project_id, user_id, page, h, v, stdout }, - 'synctex pdf output' - ) - return callback( - null, - CompileManager._parseSynctexFromPdfOutput(stdout, base_dir) - ) - }) + logger.log( + { project_id, user_id, page, h, v, stdout }, + 'synctex pdf output' + ) + return callback( + null, + CompileManager._parseSynctexFromPdfOutput(stdout, base_dir) + ) }) }, - _checkFileExists(path, callback) { + _checkFileExists(dir, filename, callback) { if (callback == null) { callback = function(error) {} } - const synctexDir = Path.dirname(path) - const synctexFile = Path.join(synctexDir, 'output.synctex.gz') - return fs.stat(synctexDir, function(error, stats) { + const file = Path.join(dir, filename) + return fs.stat(dir, function(error, stats) { if ((error != null ? error.code : undefined) === 'ENOENT') { - return callback( - new Errors.NotFoundError('called synctex with no output directory') - ) + return callback(new Errors.NotFoundError('no output directory')) } if (error != null) { return callback(error) } - return fs.stat(synctexFile, function(error, stats) { + return fs.stat(file, function(error, stats) { if ((error != null ? error.code : undefined) === 'ENOENT') { - return callback( - new Errors.NotFoundError('called synctex with no output file') - ) + return callback(new Errors.NotFoundError('no output file')) } if (error != null) { return callback(error) @@ -536,24 +510,29 @@ module.exports = CompileManager = { const directory = getCompileDir(project_id, user_id) const timeout = 60 * 1000 // increased to allow for large projects const compileName = getCompileName(project_id, user_id) - return CommandRunner.run( - compileName, - command, - directory, - Settings.clsi != null ? Settings.clsi.docker.image : undefined, - timeout, - {}, - function(error, output) { - if (error != null) { - logger.err( - { err: error, command, project_id, user_id }, - 'error running synctex' - ) - return callback(error) - } - return callback(null, output.stdout) + CompileManager._checkFileExists(directory, 'output.synctex.gz', error => { + if (error) { + return callback(error) } - ) + return CommandRunner.run( + compileName, + command, + directory, + Settings.clsi != null ? Settings.clsi.docker.image : undefined, + timeout, + {}, + function(error, output) { + if (error != null) { + logger.err( + { err: error, command, project_id, user_id }, + 'error running synctex' + ) + return callback(error) + } + return callback(null, output.stdout) + } + ) + }) }, _parseSynctexFromCodeOutput(output) { From 6569da0242bc4cb5e47e88b42218b94c08e4d345 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 12 Jun 2020 15:15:51 +0100 Subject: [PATCH 3/6] use json parsing in request --- test/acceptance/js/helpers/Client.js | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/test/acceptance/js/helpers/Client.js b/test/acceptance/js/helpers/Client.js index 9f430e3..d659416 100644 --- a/test/acceptance/js/helpers/Client.js +++ b/test/acceptance/js/helpers/Client.js @@ -81,13 +81,14 @@ module.exports = Client = { file, line, column - } + }, + json: true }, (error, response, body) => { if (error != null) { return callback(error) } - return callback(null, JSON.parse(body)) + return callback(null, body) } ) }, @@ -103,13 +104,14 @@ module.exports = Client = { page, h, v - } + }, + json: true }, (error, response, body) => { if (error != null) { return callback(error) } - return callback(null, JSON.parse(body)) + return callback(null, body) } ) }, From bad3850fcc615b3dcfca4408eddc3ca996b630c3 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 12 Jun 2020 15:16:14 +0100 Subject: [PATCH 4/6] add acceptance test for synctex when project/file does not exist --- test/acceptance/js/SynctexTests.js | 102 ++++++++++++++++++++++++++++- 1 file changed, 101 insertions(+), 1 deletion(-) diff --git a/test/acceptance/js/SynctexTests.js b/test/acceptance/js/SynctexTests.js index 4860c60..1140f3f 100644 --- a/test/acceptance/js/SynctexTests.js +++ b/test/acceptance/js/SynctexTests.js @@ -69,7 +69,7 @@ Hello world }) }) - return describe('from pdf to code', function() { + describe('from pdf to code', function() { return it('should return the correct location', function(done) { return Client.syncFromPdf( this.project_id, @@ -88,4 +88,104 @@ Hello world ) }) }) + + describe('when the project directory is not available', function() { + before(function() { + this.other_project_id = Client.randomId() + }) + describe('from code to pdf', function() { + it('should return a 404 response', function(done) { + return Client.syncFromCode( + this.other_project_id, + 'main.tex', + 3, + 5, + (error, body) => { + if (error != null) { + throw error + } + expect(body).to.equal('Not Found') + return done() + } + ) + }) + }) + describe('from pdf to code', function() { + it('should return a 404 response', function(done) { + return Client.syncFromPdf( + this.other_project_id, + 1, + 100, + 200, + (error, body) => { + if (error != null) { + throw error + } + expect(body).to.equal('Not Found') + return done() + } + ) + }) + }) + }) + + describe('when the synctex file is not available', function() { + before(function(done) { + this.broken_project_id = Client.randomId() + const content = 'this is not valid tex' // not a valid tex file + this.request = { + resources: [ + { + path: 'main.tex', + content + } + ] + } + Client.compile( + this.broken_project_id, + this.request, + (error, res, body) => { + this.error = error + this.res = res + this.body = body + return done() + } + ) + }) + + describe('from code to pdf', function() { + it('should return a 404 response', function(done) { + return Client.syncFromCode( + this.broken_project_id, + 'main.tex', + 3, + 5, + (error, body) => { + if (error != null) { + throw error + } + expect(body).to.equal('Not Found') + return done() + } + ) + }) + }) + describe('from pdf to code', function() { + it('should return a 404 response', function(done) { + return Client.syncFromPdf( + this.broken_project_id, + 1, + 100, + 200, + (error, body) => { + if (error != null) { + throw error + } + expect(body).to.equal('Not Found') + return done() + } + ) + }) + }) + }) }) From 6c7019ccb7dd3619a3d10faa2874fa43764c5e37 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Mon, 15 Jun 2020 11:06:54 +0100 Subject: [PATCH 5/6] downgrade NotFoundError log-level --- app.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app.js b/app.js index b22e0a0..ff5d70e 100644 --- a/app.js +++ b/app.js @@ -228,7 +228,7 @@ app.get('/smoke_test_force', (req, res) => smokeTest.sendNewResult(res)) app.use(function(error, req, res, next) { if (error instanceof Errors.NotFoundError) { - logger.warn({ err: error, url: req.url }, 'not found error') + logger.log({ err: error, url: req.url }, 'not found error') return res.sendStatus(404) } else if (error.code === 'EPIPE') { // inspect container returns EPIPE when shutting down From 74a11c7be31d5ca385a9aed8a20d48ea4a8f98cb Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Tue, 16 Jun 2020 08:45:53 +0100 Subject: [PATCH 6/6] fix format --- app/js/DockerRunner.js | 1 - 1 file changed, 1 deletion(-) diff --git a/app/js/DockerRunner.js b/app/js/DockerRunner.js index e75b997..21ea97f 100644 --- a/app/js/DockerRunner.js +++ b/app/js/DockerRunner.js @@ -27,7 +27,6 @@ const fs = require('fs') const Path = require('path') const _ = require('lodash') - logger.info('using docker runner') const usingSiblingContainers = () =>