test: show lldb output when timing out

nodejs · joyeecheung · Nov 30, 2017 · Nov 28, 2017 · Nov 3, 2017 · Nov 28, 2017
commit b36fbc0bd2bd0f993b199edf5f151c531d45dc68
diff --git a/test/common.js b/test/common.js
@@ -8,27 +8,39 @@ const spawn = require('child_process').spawn;
 const EventEmitter = require('events').EventEmitter;
 
 exports.fixturesDir = path.join(__dirname, 'fixtures');
-exports.buildDir = path.join(__dirname, '..', 'out', 'Release');
+exports.projectDir = path.join(__dirname, '..');
 
 exports.core = path.join(os.tmpdir(), 'core');
-exports.ranges = exports.core + '.ranges';
+exports.promptDelay = 200;
+
+function llnodeDebug() {
+  // Node v4.x does not support rest
+  const args = Array.prototype.slice.call(arguments);
+  console.error.apply(console, [`[TEST][${process.pid}]`].concat(args));
+}
+
+const debug = exports.debug =
+  process.env.TEST_LLNODE_DEBUG ? llnodeDebug : () => { };
 
 let pluginName;
 if (process.platform === 'darwin')
   pluginName = 'llnode.dylib';
 else if (process.platform === 'windows')
   pluginName = 'llnode.dll';
 else
-  pluginName = path.join('lib.target', 'llnode.so');
+  pluginName = 'llnode.so';
 
-exports.llnodePath = path.join(exports.buildDir, pluginName);
+exports.llnodePath = path.join(exports.projectDir, pluginName);
+exports.saveCoreTimeout = 180 * 1000;
+exports.loadCoreTimeout = 20 * 1000;
 
-function SessionOutput(session, stream) {
+function SessionOutput(session, stream, timeout) {
   EventEmitter.call(this);
   this.waiting = false;
   this.waitQueue = [];
-
   let buf = '';
+  this.timeout = timeout || 10000;
+  this.session = session;
 
   stream.on('data', (data) => {
     buf += data;
@@ -44,10 +56,8 @@ function SessionOutput(session, stream) {
 
       if (/process \d+ exited/i.test(line))
         session.kill();
-      else if (session.initialized)
+      else
         this.emit('line', line);
-      else if (/process \d+ launched/i.test(line))
-        session.initialized = true;
     }
   });
 
@@ -72,109 +82,173 @@ SessionOutput.prototype._unqueueWait = function _unqueueWait() {
     this.waitQueue.shift()();
 };
 
-SessionOutput.prototype.wait = function wait(regexp, callback) {
-  if (!this._queueWait(() => { this.wait(regexp, callback); }))
-    return;
-
-  const self = this;
-  this.on('line', function onLine(line) {
-    if (!regexp.test(line))
-      return;
-
-    self.removeListener('line', onLine);
-    self._unqueueWait();
-
-    callback(line);
-  });
-};
-
-SessionOutput.prototype.waitBreak = function waitBreak(callback) {
-  this.wait(/Process \d+ stopped/i, callback);
+SessionOutput.prototype.timeoutAfter = function timeoutAfter(timeout) {
+  this.timeout = timeout;
 };
 
-SessionOutput.prototype.linesUntil = function linesUntil(regexp, callback) {
-  if (!this._queueWait(() => { this.linesUntil(regexp, callback); }))
+SessionOutput.prototype.wait = function wait(regexp, callback, allLines) {
+  if (!this._queueWait(() => { this.wait(regexp, callback, allLines); }))
     return;
 
-  const lines = [];
   const self = this;
-  this.on('line', function onLine(line) {
+  const lines = [];
+
+  function onLine(line) {
     lines.push(line);
+    debug('[LINE]', line);
 
     if (!regexp.test(line))
       return;
 
     self.removeListener('line', onLine);
     self._unqueueWait();
+    done = true;
 
-    callback(lines);
+    callback(allLines ? lines : line);
+  }
+
+  let done = false;
+  let timePassed = 0;
+  const interval = 100;
+  const check = setInterval(() => {
+    timePassed += interval;
+    if (done)
+      clearInterval(check);
+
+    if (timePassed > self.timeout) {
+      self.removeListener('line', onLine);
+      self._unqueueWait();
+      const message = `Test timeout in ${this.timeout} ` +
+        `waiting for ${regexp}\n` +
+        `\n${'='.repeat(10)} lldb output ${'='.repeat(10)}\n` +
+        `\n${lines.join('\n')}` +
+        `\n${'='.repeat(30)}\n`;
+      throw new Error(message);
+    }
+  }, interval);
+
+  this.on('line', onLine);
+};
+
+SessionOutput.prototype.waitBreak = function waitBreak(callback) {
+  this.wait(/Process \d+ stopped/i, () => {
+    // Do not resume immediately since the process would print
+    // the instructions out and input sent before the stdout finish
+    // could be lost
+    setTimeout(callback, exports.promptDelay);
   });
 };
 
+SessionOutput.prototype.linesUntil = function linesUntil(regexp, callback) {
+  this.wait(regexp, callback, true);
+};
 
-function Session(scenario) {
+function Session(options) {
   EventEmitter.call(this);
+  const timeout = parseInt(process.env.TEST_TIMEOUT) || 10000;
+  const lldbBin = process.env.TEST_LLDB_BINARY || 'lldb';
+  const env = Object.assign({}, process.env);
+
+  if (options.ranges)
+    env.LLNODE_RANGESFILE = options.ranges;
+
+  debug('lldb binary:', lldbBin);
+  if (options.scenario) {
+    this.needToKill = true;
+    // lldb -- node scenario.js
+    const args = [
+      '--',
+      process.execPath,
+      '--abort_on_uncaught_exception',
+      '--expose_externalize_string',
+      path.join(exports.fixturesDir, options.scenario)
+    ];
+
+    debug('lldb args:', args);
+    this.lldb = spawn(lldbBin, args, {
+      stdio: ['pipe', 'pipe', 'pipe'],
+      env: env
+    });
+    this.lldb.stdin.write(`plugin load "${exports.llnodePath}"\n`);
+    this.lldb.stdin.write('run\n');
+  } else if (options.core) {
+    this.needToKill = false;
+    debug('loading core', options.core);
+    // lldb node -c core
+    this.lldb = spawn(lldbBin, [], {
+      stdio: ['pipe', 'pipe', 'pipe'],
+      env: env
+    });
+    this.lldb.stdin.write(`plugin load "${exports.llnodePath}"\n`);
+    this.lldb.stdin.write(`target create "${options.executable}"` +
+      ` --core "${options.core}"\n`);
+  }
+  this.stdout = new SessionOutput(this, this.lldb.stdout, timeout);
+  this.stderr = new SessionOutput(this, this.lldb.stderr, timeout);
 
-  // lldb -- node scenario.js
-  this.lldb = spawn(process.env.TEST_LLDB_BINARY || 'lldb', [
-    '--',
-    process.execPath,
-    '--abort_on_uncaught_exception',
-    '--expose_externalize_string',
-    path.join(exports.fixturesDir, scenario)
-  ], {
-    stdio: [ 'pipe', 'pipe', 'pipe' ],
-    env: util._extend(util._extend({}, process.env), {
-      LLNODE_RANGESFILE: exports.ranges
-    })
+  this.stderr.on('line', (line) => {
+    debug('[stderr]', line);
   });
 
-  this.lldb.stdin.write(`plugin load "${exports.llnodePath}"\n`);
-  this.lldb.stdin.write('run\n');
-
-  this.initialized = false;
-  this.stdout = new SessionOutput(this, this.lldb.stdout);
-  this.stderr = new SessionOutput(this, this.lldb.stderr);
-
   // Map these methods to stdout for compatibility with legacy tests.
   this.wait = SessionOutput.prototype.wait.bind(this.stdout);
   this.waitBreak = SessionOutput.prototype.waitBreak.bind(this.stdout);
   this.linesUntil = SessionOutput.prototype.linesUntil.bind(this.stdout);
+  this.timeoutAfter = SessionOutput.prototype.timeoutAfter.bind(this.stdout);
 }
 util.inherits(Session, EventEmitter);
 exports.Session = Session;
 
 Session.create = function create(scenario) {
-  return new Session(scenario);
+  return new Session({ scenario: scenario });
+};
+
+Session.loadCore = function loadCore(executable, core, ranges) {
+  return new Session({
+    executable: executable,
+    core: core,
+    ranges: ranges
+  });
+};
+
+Session.prototype.waitCoreLoad = function waitCoreLoad(callback) {
+  this.wait(/Core file[^\n]+was loaded/, callback);
 };
 
 Session.prototype.kill = function kill() {
-  this.lldb.kill();
-  this.lldb = null;
+  // if a 'quit' has been sent to lldb, killing it could result in ECONNRESET
+  if (this.lldb.channel) {
+    debug('kill lldb');
+    this.lldb.kill();
+    this.lldb = null;
+  }
 };
 
 Session.prototype.quit = function quit() {
-  this.send('kill');
+  if (this.needToKill)
+    this.send('kill'); // kill the process launched in lldb
+
   this.send('quit');
 };
 
 Session.prototype.send = function send(line, callback) {
+  debug('[SEND]', line);
   this.lldb.stdin.write(line + '\n', callback);
 };
 
-
-exports.generateRanges = function generateRanges(cb) {
+exports.generateRanges = function generateRanges(core, dest, cb) {
   let script;
   if (process.platform === 'darwin')
     script = path.join(__dirname, '..', 'scripts', 'otool2segments.py');
   else
     script = path.join(__dirname, '..', 'scripts', 'readelf2segments.py');
 
-  const proc = spawn(script, [ exports.core ], {
-    stdio: [ null, 'pipe', 'inherit' ]
+  debug('[RANGES]', `${script}, ${core}, ${dest}`);
+  const proc = spawn(script, [core], {
+    stdio: [null, 'pipe', 'inherit']
   });
 
-  proc.stdout.pipe(fs.createWriteStream(exports.ranges));
+  proc.stdout.pipe(fs.createWriteStream(dest));
 
   proc.on('exit', (status) => {
     cb(status === 0 ? null : new Error('Failed to generate ranges'));

diff --git a/test/inspect-test.js b/test/inspect-test.js
@@ -190,10 +190,8 @@ tape('v8 inspect', (t) => {
         lines.indexOf('<Array: length=20'),
         -1,
         'long array length');
-      t.ok(
-          lines.match(/\[9\]=<Smi: 5>}>$/),
-          'long array content');
-      sess.send(`v8 inspect ${arrayBuffer}`);
+    t.ok(lines.match(/\[9\]=<Smi: 5>}>$/), 'long array content');
+    sess.send(`v8 inspect ${arrayBuffer}`);
   });
 
   sess.linesUntil(/\]>/, (lines) => {
@@ -286,7 +284,7 @@ tape('v8 inspect', (t) => {
     // the function we want.)
     const arrowSource = 'source:\n' +
         'function c.hashmap.(anonymous function)(a,b)=>{a+b}\n' +
-        '>'
+        '>';
 
     t.ok(lines.includes(
         arrowSource),
@@ -301,11 +299,11 @@ tape('v8 inspect', (t) => {
     // Include 'source:' and '>' to act as boundaries. (Avoid
     // passing if the whole file it displayed instead of just
     // the function we want.)
-    const methodSource = "  source:\n" +
-    "function method() {\n" +
-    "    throw new Error('Uncaught');\n" +
-    "  }\n" +
-    ">"
+    const methodSource = '  source:\n' +
+    'function method() {\n' +
+    '    throw new Error(\'Uncaught\');\n' +
+    '  }\n' +
+    '>';
 
     t.ok(lines.includes(
         methodSource),