diff --git a/lib/Local.js b/lib/Local.js index 05d29e0..ffd8af9 100644 --- a/lib/Local.js +++ b/lib/Local.js @@ -58,6 +58,11 @@ function Local(){ } try{ const obj = childProcess.spawnSync(that.binaryPath, that.getBinaryArgs()); + /* stdout is null on a spawn failure; reading .length masked the real cause + and the binary was deleted on a TypeError rather than the actual error. */ + if(obj.error) { + throw obj.error; + } this.tunnel = {pid: obj.pid}; var data = {}; if(obj.stdout.length > 0) @@ -79,7 +84,12 @@ function Local(){ if(that.retriesLeft > 0) { console.log('Retrying Binary Download. Retries Left', that.retriesLeft); that.retriesLeft -= 1; - fs.unlinkSync(that.binaryPath); + if(that.binary) that.binary.waitWhileBinaryBusySync(that.binaryPath); + try { fs.unlinkSync(that.binaryPath); } catch(err) { /* ignored */ } + /* Still there: binaryPath() would hand back the same unusable file. */ + if(fs.existsSync(that.binaryPath)) { + return new LocalError(binaryDownloadErrorMessage); + } delete(that.binaryPath); that.binaryDownloadState.errorMessage = binaryDownloadErrorMessage; that.binaryDownloadState.fallbackEnabled = true; @@ -99,6 +109,11 @@ function Local(){ return callback(); this.getBinaryPath(function(binaryPath){ + /* Matches startSync's check below: the download can exhaust its retries + and hand back nothing, and execFile(undefined) throws uncatchably. */ + if(!binaryPath) { + return callback(new LocalError('Couldn\'t find binary file')); + } that.binaryPath = binaryPath; try { fs.writeFileSync(that.logfile, ''); @@ -114,11 +129,21 @@ function Local(){ if(that.retriesLeft > 0) { console.log('Retrying Binary Download. Retries Left', that.retriesLeft); that.retriesLeft -= 1; - fs.unlinkSync(that.binaryPath); - delete(that.binaryPath); - that.binaryDownloadState.errorMessage = binaryDownloadErrorMessage; - that.binaryDownloadState.fallbackEnabled = true; - that.start(options, callback); + var replace = function(waitsLeft) { + if(waitsLeft > 0 && fs.existsSync(that.binaryPath) && + that.binary && that.binary.isBinaryBusy(that.binaryPath)) { + return setTimeout(function() { replace(waitsLeft - 1); }, 1000); + } + try { fs.unlinkSync(that.binaryPath); } catch(err) { /* ignored */ } + if(fs.existsSync(that.binaryPath)) { + return callback(new LocalError(binaryDownloadErrorMessage)); + } + delete(that.binaryPath); + that.binaryDownloadState.errorMessage = binaryDownloadErrorMessage; + that.binaryDownloadState.fallbackEnabled = true; + that.start(options, callback); + }; + replace(3); return; } else { callback(new LocalError(error.toString())); diff --git a/lib/LocalBinary.js b/lib/LocalBinary.js index 00e1748..632d88b 100644 --- a/lib/LocalBinary.js +++ b/lib/LocalBinary.js @@ -1,3 +1,5 @@ +/* global Atomics, SharedArrayBuffer -- ES2017, used for the blocking wait in + waitWhileBinaryBusySync; declared here rather than widening the lint env. */ var https = require('https'), fs = require('fs'), path = require('path'), @@ -71,6 +73,10 @@ function LocalBinary(){ env.BROWSERSTACK_LOCAL_AUTH_TOKEN = this.key; } const obj = childProcess.spawnSync(cmd, opts, { env: env }); + /* stdout is null on a spawn failure; reading .length masked the real cause. */ + if(obj.error) { + throw(util.format(obj.error)); + } if(obj.stdout.length > 0) { this.sourceURL = obj.stdout.toString().replace(/\n+$/, ''); this.downloadState.sourceURL = this.sourceURL; @@ -148,23 +154,60 @@ function LocalBinary(){ this.downloadErrorMessage = errorMessagePrefix + ' : ' + errorMessage; }; + /* A locked binary is transient on Windows (AV scan, a tunnel still releasing + its handle), not a corrupt one. Mirrors the CLI binary's existing probe. */ + this.BUSY_ERROR_CODES = ['EBUSY', 'EPERM', 'ETXTBSY', 'EACCES']; + this.BUSY_MAX_WAITS = 3; + this.BUSY_WAIT_MS = 1000; + + this.isBinaryBusy = function(binaryPath) { + try { + fs.closeSync(fs.openSync(binaryPath, 'r+')); + return false; + } catch(err) { + return this.BUSY_ERROR_CODES.indexOf(err.code) !== -1; + } + }; + + /* Blocking by design: the sync path has no event loop to come back to. */ + this.waitWhileBinaryBusySync = function(binaryPath) { + for(var i = 0; i < this.BUSY_MAX_WAITS; i++) { + if(!fs.existsSync(binaryPath) || !this.isBinaryBusy(binaryPath)) return; + console.log('Binary is in use, waiting before retrying.'); + Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, this.BUSY_WAIT_MS); + } + }; + this.retryBinaryDownload = function(conf, destParentDir, callback, retries, binaryPath) { var that = this; - if(retries > 0) { - console.log('Retrying Download. Retries left', retries); - /* Single unlink instead of stat-then-unlinkSync: the gap between the two - let a concurrent writer swap the file, and a failing unlinkSync threw - out of the stat callback where it could not be caught. A missing file - is the expected case here, so any error is ignored. */ + if(retries <= 0) { + console.error('Number of retries to download exceeded.'); + /* The async contract has to be completed or Local.start() waits forever. + An empty path is the signal; the caller reports it. */ + if(callback) callback(); + return; + } + console.log('Retrying Download. Retries left', retries); + + /* Must stay synchronous: this return value is what downloadSync -> + binaryPath() -> Local.getBinaryPath hands back. Retrying inside a callback + returned undefined before the retry had done anything. */ + if(!callback) { + that.waitWhileBinaryBusySync(binaryPath); + try { fs.unlinkSync(binaryPath); } catch(err) { /* missing or locked */ } + return that.downloadSync(conf, destParentDir, retries - 1); + } + + var attemptAsync = function(waitsLeft) { + if(waitsLeft > 0 && fs.existsSync(binaryPath) && that.isBinaryBusy(binaryPath)) { + console.log('Binary is in use, waiting before retrying.'); + return setTimeout(function() { attemptAsync(waitsLeft - 1); }, that.BUSY_WAIT_MS); + } fs.unlink(binaryPath, function() { - if(!callback) { - return that.downloadSync(conf, destParentDir, retries - 1); - } that.download(conf, destParentDir, callback, retries - 1); }); - } else { - console.error('Number of retries to download exceeded.'); - } + }; + attemptAsync(that.BUSY_MAX_WAITS); }; this.downloadSync = function(conf, destParentDir, retries) { @@ -198,6 +241,14 @@ function LocalBinary(){ const userAgent = [packageName, version].join('/'); const env = Object.assign({ 'USER_AGENT': userAgent }, process.env); const obj = childProcess.spawnSync(cmd, opts, { env: env }); + if(obj.status !== 0) { + that.binaryDownloadError('Download failed with status', String(obj.status)); + return that.retryBinaryDownload(conf, destParentDir, null, retries, binaryPath); + } + if(obj.error) { + that.binaryDownloadError('Download failed with error', util.format(obj.error)); + return that.retryBinaryDownload(conf, destParentDir, null, retries, binaryPath); + } let output; if(obj.stdout.length > 0) { if(fs.existsSync(binaryPath)){ @@ -221,7 +272,8 @@ function LocalBinary(){ this.download = function(conf, destParentDir, callback, retries){ this.getDownloadPath(conf, retries, (err, downloadUrl) => { if(err) { - return console.error('Unable to fetch the source url to download the binary with error: ', err); + console.error('Unable to fetch the source url to download the binary with error: ', err); + return callback(); } this.httpPath = downloadUrl; @@ -234,6 +286,21 @@ function LocalBinary(){ var binaryPath = path.join(destParentDir, destBinaryName); var fileStream = fs.createWriteStream(binaryPath); + /* A failed open and the in-flight request can both report on the same + attempt; one attempt must trigger at most one retry. */ + var retried = false; + var retryOnce = function(prefix, err) { + that.binaryDownloadError(prefix, util.format(err)); + if(retried) return; + retried = true; + that.retryBinaryDownload(conf, destParentDir, callback, retries, binaryPath); + }; + + /* Same as lib/download.js: the open() failure lands first. */ + fileStream.on('error', function (err) { + retryOnce('Got Error while downloading binary file', err); + }); + var options = url.parse(this.httpPath); if(conf.proxyHost && conf.proxyPort) { options.agent = new HttpsProxyAgent({ @@ -267,21 +334,18 @@ function LocalBinary(){ } response.on('error', function(err) { - that.binaryDownloadError('Got Error in binary download response', util.format(err)); - that.retryBinaryDownload(conf, destParentDir, callback, retries, binaryPath); - }); - fileStream.on('error', function (err) { - that.binaryDownloadError('Got Error while downloading binary file', util.format(err)); - that.retryBinaryDownload(conf, destParentDir, callback, retries, binaryPath); + retryOnce('Got Error in binary download response', err); }); fileStream.on('close', function () { + /* node emits 'close' after 'error' too, so without this a failed + attempt reports success alongside the retry it just started. */ + if(retried) return; fs.chmod(binaryPath, '0755', function() { callback(binaryPath); }); }); }).on('error', function(err) { - that.binaryDownloadError('Got Error in binary downloading request', util.format(err)); - that.retryBinaryDownload(conf, destParentDir, callback, retries, binaryPath); + retryOnce('Got Error in binary downloading request', err); }); }); }; diff --git a/lib/download.js b/lib/download.js index dde74a2..2d54cc4 100644 --- a/lib/download.js +++ b/lib/download.js @@ -9,6 +9,18 @@ const binaryPath = process.argv[2], httpPath = process.argv[3], proxyHost = proc var fileStream = fs.createWriteStream(binaryPath); +/* Must be attached before the async https.get: createWriteStream emits 'error' + on the next tick, and with no listener node turns that into a hard throw. */ +var request; + +fileStream.on('error', function (err) { + console.error('Got Error while downloading binary file', err); + process.exitCode = 1; + /* Otherwise the child keeps downloading into a dead stream and the parent's + spawnSync blocks for a whole download before it can retry. */ + if(request) request.destroy(); +}); + var options = url.parse(httpPath); /* isUndefined, not plain truthiness: the parent passes literal `undefined` placeholders for the proxy slots when only a CA is configured, and those @@ -37,7 +49,7 @@ options.headers = Object.assign({}, options.headers, { 'user-agent': process.env.USER_AGENT, }); -https.get(options, function (response) { +request = https.get(options, function (response) { const contentEncoding = response.headers['content-encoding']; if (typeof contentEncoding === 'string' && contentEncoding.match(/gzip/i)) { if (process.env.BROWSERSTACK_LOCAL_DEBUG_GZIP) { @@ -52,12 +64,11 @@ https.get(options, function (response) { response.on('error', function(err) { console.error('Got Error in binary download response', err); }); - fileStream.on('error', function (err) { - console.error('Got Error while downloading binary file', err); - }); fileStream.on('close', function () { + if(process.exitCode === 1) return; // errored; not a completed download console.log('Done'); }); }).on('error', function(err) { + if(process.exitCode === 1) return; // our own destroy() landing console.error('Got Error in binary downloading request', err); }); diff --git a/test/local_binary_busy_download.js b/test/local_binary_busy_download.js new file mode 100644 index 0000000..d7a70fb --- /dev/null +++ b/test/local_binary_busy_download.js @@ -0,0 +1,176 @@ +var expect = require('expect.js'), + childProcess = require('child_process'), + fs = require('fs'), + os = require('os'), + path = require('path'), + LocalBinary = require('../lib/LocalBinary'), + browserstack = require('../index'); + +// Regression tests for LOC-7420. +// +// On Windows `BrowserStackLocal.exe` in ~/.browserstack is routinely +// unopenable for a moment — an AV scan of a freshly written executable, a +// tunnel still releasing its handle, two workers starting at once — and the +// open fails with EBUSY/EPERM. Two defects turned that transient condition +// into a hard failure: +// +// 1. `download.js` attached its write-stream 'error' handler inside the +// async https.get callback, so the open failure arrived with no listener +// and node killed the download child with an unhandled 'error'. +// 2. `retryBinaryDownload` did its work inside an async callback, so on the +// sync path it returned undefined to a caller that had already given up — +// surfacing as "Couldn't find binary file" while the retries carried on, +// orphaned, in the background. +// +// Neither needs Windows to reproduce: (1) is any createWriteStream failure, +// and (2) is platform-independent. +describe('LocalBinary busy-binary download handling', function () { + + describe('retryBinaryDownload', function () { + it('returns the retry result to the caller on the sync path', function () { + var binary = new LocalBinary(), + expected = path.join(os.tmpdir(), 'BrowserStackLocal-fake'), + calls = 0; + + // First attempt fails and retries; the retry succeeds. Before the fix + // the returned value was lost in the async callback. + binary.downloadSync = function (conf, dest, retries) { + calls += 1; + if (calls === 1) { + return binary.retryBinaryDownload(conf, dest, null, retries, path.join(os.tmpdir(), 'bs-local-absent')); + } + return expected; + }; + + expect(binary.downloadSync({}, os.tmpdir(), 9)).to.equal(expected); + expect(calls).to.equal(2); + }); + + it('stops at the retry ceiling instead of recursing', function () { + var binary = new LocalBinary(), calls = 0; + binary.downloadSync = function (conf, dest, retries) { + calls += 1; + return binary.retryBinaryDownload(conf, dest, null, retries, path.join(os.tmpdir(), 'bs-local-absent')); + }; + + // One initial attempt plus `retries` further ones, then a clean stop. + expect(binary.downloadSync({}, os.tmpdir(), 3)).to.be(undefined); + expect(calls).to.equal(4); + }); + }); + + describe('async download completion', function () { + // The callback contract has to be completed on every path, or + // Local.start() waits on a callback that never arrives. + it('completes the callback when retries are exhausted', function (done) { + var binary = new LocalBinary(); + binary.retryBinaryDownload({}, os.tmpdir(), function (binaryPath) { + expect(binaryPath).to.be(undefined); + done(); + }, 0, path.join(os.tmpdir(), 'bs-local-absent')); + }); + + // node emits 'close' after 'error', so a failed attempt used to report + // success through the close handler as well as retrying. + it('reports a failed attempt once, not alongside a success', function (done) { + var dir = fs.mkdtempSync(path.join(os.tmpdir(), 'bs-local-')), + target = path.join(dir, 'BrowserStackLocal'), + calls = []; + fs.mkdirSync(target); + + var binary = new LocalBinary(); + binary.getDownloadPath = function (conf, retries, cb) { + cb(null, 'https://127.0.0.1:1/BrowserStackLocal'); + }; + binary.download({}, dir, function (binaryPath) { calls.push(binaryPath); }, 0); + + setTimeout(function () { + expect(calls.length).to.equal(1); + expect(calls[0]).to.be(undefined); + fs.rmdirSync(target); + fs.rmdirSync(dir); + done(); + }, 1500); + }); + }); + + describe('source url failure', function () { + it('completes the callback when the download url cannot be fetched', function (done) { + var binary = new LocalBinary(); + binary.getDownloadPath = function (conf, retries, cb) { cb(new Error('invalid key')); }; + binary.download({}, os.tmpdir(), function (binaryPath) { + expect(binaryPath).to.be(undefined); + done(); + }, 9); + }); + }); + + describe('unremovable binary', function () { + // An unusable binary whose unlink fails used to be handed straight back by + // binaryPath() and re-spawned for every remaining retry. + it('does not retry when the binary cannot be replaced', function () { + var dir = fs.mkdtempSync(path.join(os.tmpdir(), 'bs-local-')), + binaryPath = path.join(dir, 'BrowserStackLocal'); + fs.writeFileSync(binaryPath, 'not executable', { mode: 0o644 }); + fs.chmodSync(dir, 0o555); // so the unlink fails + + try { + var bsLocal = new browserstack.Local(); + bsLocal.binaryPath = binaryPath; + var result = bsLocal.startSync({ key: 'dummy-key' }); + + expect(result).to.be.a(Object); + expect(result.message).to.contain('Error while trying to execute binary'); + expect(bsLocal.retriesLeft).to.equal(8); // one attempt, not nine + } finally { + fs.chmodSync(dir, 0o755); + fs.unlinkSync(binaryPath); + fs.rmdirSync(dir); + } + }); + }); + + describe('isBinaryBusy', function () { + it('reports a readable file as free', function () { + var binary = new LocalBinary(), + probe = path.join(os.tmpdir(), 'bs-local-probe-' + process.pid); + fs.writeFileSync(probe, 'x'); + try { + expect(binary.isBinaryBusy(probe)).to.be(false); + } finally { + fs.unlinkSync(probe); + } + }); + + it('does not report a missing file as busy', function () { + var binary = new LocalBinary(); + expect(binary.isBinaryBusy(path.join(os.tmpdir(), 'bs-local-absent-' + process.pid))).to.be(false); + }); + }); + + describe('download.js', function () { + // The open failure is forced with a directory at the target path. The + // errno differs from Windows' EBUSY (-4082); the code path is the same. + it('reports an unwritable target without crashing the child', function () { + var dir = fs.mkdtempSync(path.join(os.tmpdir(), 'bs-local-')), + target = path.join(dir, 'BrowserStackLocal'); + fs.mkdirSync(target); + + var obj = childProcess.spawnSync(process.execPath, [ + path.join(__dirname, '..', 'lib', 'download.js'), + target, + 'https://local-downloads.browserstack.com/binaries/release/latest_unzip/BrowserStackLocal' + ], { env: Object.assign({ USER_AGENT: 'browserstack-local-test' }, process.env) }); + + var stderr = obj.stderr.toString(); + expect(stderr).to.contain('Got Error while downloading binary file'); + // The signature of the old defect: node's unhandled-'error' bail-out. + expect(stderr).to.not.contain('Unhandled \'error\' event'); + expect(obj.stdout.toString()).to.not.contain('Done'); + expect(obj.status).to.equal(1); + + fs.rmdirSync(target); + fs.rmdirSync(dir); + }); + }); +});