LOC-7420: tolerate a busy binary instead of crashing the consumer

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,8 @@ function Local(){
       if(that.retriesLeft > 0) {
         console.log('Retrying Binary Download. Retries Left', that.retriesLeft);
         that.retriesLeft -= 1;
-        fs.unlinkSync(that.binaryPath);
+        /* EPERM on a locked file threw straight out of startSync. */
+        try { fs.unlinkSync(that.binaryPath); } catch(err) { /* ignored */ }
         delete(that.binaryPath);
         that.binaryDownloadState.errorMessage = binaryDownloadErrorMessage;
         that.binaryDownloadState.fallbackEnabled = true;
@@ -99,6 +105,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,7 +125,7 @@ function Local(){
           if(that.retriesLeft > 0) {
             console.log('Retrying Binary Download. Retries Left', that.retriesLeft);
             that.retriesLeft -= 1;
-            fs.unlinkSync(that.binaryPath);
+            try { fs.unlinkSync(that.binaryPath); } catch(err) { /* ignored */ }
             delete(that.binaryPath);
             that.binaryDownloadState.errorMessage = binaryDownloadErrorMessage;
             that.binaryDownloadState.fallbackEnabled = true;

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,10 @@ 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.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)){
@@ -234,6 +281,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 +329,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);
       });
     });
   };

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,10 @@ 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 () {
     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);
 });

test/local_binary_busy_download.js

@@ -0,0 +1,138 @@
+var expect = require('expect.js'),
+    childProcess = require('child_process'),
+    fs = require('fs'),
+    os = require('os'),
+    path = require('path'),
+    LocalBinary = require('../lib/LocalBinary');
+
+// 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('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.status).to.equal(1);
+
+      fs.rmdirSync(target);
+      fs.rmdirSync(dir);
+    });
+  });
+});