Bug 896087 - Output structured messages in head.js, interpret them in runxpcshelltests.py; r=ted

testing/xpcshell/head.js

@@ -19,6 +19,15 @@ var _cleanupFunctions = [];
 var _pendingTimers = [];
 var _profileInitialized = false;
 
+let _log = function (action, params) {
+  if (typeof _XPCSHELL_PROCESS != "undefined") {
+    params.process = _XPCSHELL_PROCESS;
+  }
+  params.action = action;
+  params._time = Date.now();
+  dump("\n" + JSON.stringify(params) + "\n");
+}
+
 function _dump(str) {
   let start = /^TEST-/.test(str) ? "\n" : "";
   if (typeof _XPCSHELL_PROCESS == "undefined") {
@@ -154,7 +163,8 @@ function _do_main() {
   if (_quit)
     return;
 
-  _dump("TEST-INFO | (xpcshell/head.js) | running event loop\n");
+  _log("test_info",
+       {_message: "TEST-INFO | (xpcshell/head.js) | running event loop\n"});
 
   var thr = Components.classes["@mozilla.org/thread-manager;1"]
                       .getService().currentThread;
@@ -167,24 +177,29 @@ function _do_main() {
 }
 
 function _do_quit() {
-  _dump("TEST-INFO | (xpcshell/head.js) | exiting test\n");
+  _log("test_info",
+       {_message: "TEST-INFO | (xpcshell/head.js) | exiting test\n"});
 
   _quit = true;
 }
 
-function _dump_exception_stack(stack) {
+function _format_exception_stack(stack) {
-  stack.split("\n").forEach(function(frame) {
+  // frame is of the form "fname(args)@file:line"
-    if (!frame)
+  let frame_regexp = new RegExp("(.*)\\(.*\\)@(.*):(\\d*)", "g");
-      return;
+  return stack.split("\n").reduce(function(stack_msg, frame) {
-    // frame is of the form "fname(args)@file:line"
+    if (frame) {
-    let frame_regexp = new RegExp("(.*)\\(.*\\)@(.*):(\\d*)", "g");
+      let parts = frame_regexp.exec(frame);
-    let parts = frame_regexp.exec(frame);
+      if (parts) {
-    if (parts)
+        return stack_msg + "JS frame :: " + parts[2] + " :: " +
-        dump("JS frame :: " + parts[2] + " :: " + (parts[1] ? parts[1] : "anonymous")
+          (parts[1] ? parts[1] : "anonymous") +
-             + " :: line " + parts[3] + "\n");
+          " :: line " + parts[3] + "\n";
-    else /* Could be a -e (command line string) style location. */
+      }
-        dump("JS frame :: " + frame + "\n");
+      else { /* Could be a -e (command line string) style location. */
-  });
+        return stack_msg + "JS frame :: " + frame + "\n";
+      }
+    }
+    return stack_msg;
+  }, "");
 }
 
 /**
@@ -341,23 +356,21 @@ function _execute_test() {
     // possible that this will mask an NS_ERROR_ABORT that happens after a
     // do_check failure though.
     if (!_quit || e != Components.results.NS_ERROR_ABORT) {
-      let msg = "TEST-UNEXPECTED-FAIL | ";
+      let msgObject = {};
       if (e.fileName) {
-        msg += e.fileName;
+        msgObject.source_file = e.fileName;
         if (e.lineNumber) {
-          msg += ":" + e.lineNumber;
+          msgObject.line_number = e.lineNumber;
         }
       } else {
-        msg += "xpcshell/head.js";
+        msgObject.source_file = "xpcshell/head.js";
       }
-      msg += " | " + e;
+      msgObject.diagnostic = _exception_message(e);
       if (e.stack) {
-        _dump(msg + " - See following stack:\n");
+        msgObject.diagnostic += " - See following stack:\n";
-        _dump_exception_stack(e.stack);
+        msgObject.stack = _format_exception_stack(e.stack);
-      }
-      else {
-        _dump(msg + "\n");
       }
+      _log("test_unexpected_fail", msgObject);
     }
   }
 
@@ -377,13 +390,22 @@ function _execute_test() {
 
   var truePassedChecks = _passedChecks - _falsePassedChecks;
   if (truePassedChecks > 0) {
-    _dump("TEST-PASS | (xpcshell/head.js) | " + truePassedChecks + " (+ " +
+    _log("test_pass",
-            _falsePassedChecks + ") check(s) passed\n");
+         {_message: "TEST-PASS | (xpcshell/head.js) | " + truePassedChecks + " (+ " +
-    _dump("TEST-INFO | (xpcshell/head.js) | " + _todoChecks +
+                    _falsePassedChecks + ") check(s) passed\n",
-            " check(s) todo\n");
+          source_file: _TEST_FILE,
+          passed_checks: truePassedChecks});
+    _log("test_info",
+         {_message: "TEST-INFO | (xpcshell/head.js) | " + _todoChecks +
+                    " check(s) todo\n",
+          source_file: _TEST_FILE,
+          todo_checks: _todoChecks});
   } else {
     // ToDo: switch to TEST-UNEXPECTED-FAIL when all tests have been updated. (Bug 496443)
-    _dump("TEST-INFO | (xpcshell/head.js) | No (+ " + _falsePassedChecks + ") checks actually run\n");
+    _log("test_info",
+         {_message: "TEST-INFO | (xpcshell/head.js) | No (+ " + _falsePassedChecks +
+                    ") checks actually run\n",
+         source_file: _TEST_FILE});
   }
 }
 
@@ -394,7 +416,15 @@ function _execute_test() {
  */
 function _load_files(aFiles) {
   function loadTailFile(element, index, array) {
-    load(element);
+    try {
+      load(element);
+    } catch (e if e instanceof SyntaxError) {
+      _log("javascript_error",
+           {_message: "TEST-UNEXPECTED-FAIL | (xpcshell/head.js) | Source file " + element + " contains SyntaxError",
+            diagnostic: _exception_message(e),
+            source_file: element,
+            stack: _format_exception_stack(e.stack)});
+    }
   }
 
   aFiles.forEach(loadTailFile);
@@ -412,7 +442,10 @@ function _wrap_with_quotes_if_necessary(val) {
 function do_print(msg) {
   var caller_stack = Components.stack.caller;
   msg = _wrap_with_quotes_if_necessary(msg);
-  _dump("TEST-INFO | " + caller_stack.filename + " | " + msg + "\n");
+  _log("test_info",
+       {source_file: caller_stack.filename,
+        diagnostic: msg});
+
 }
 
 /**
@@ -446,13 +479,15 @@ function do_execute_soon(callback, aName) {
         // possible that this will mask an NS_ERROR_ABORT that happens after a
         // do_check failure though.
         if (!_quit || e != Components.results.NS_ERROR_ABORT) {
-          _dump("TEST-UNEXPECTED-FAIL | (xpcshell/head.js) | " + e);
           if (e.stack) {
-            dump(" - See following stack:\n");
+            _log("javascript_error",
-            _dump_exception_stack(e.stack);
+                 {source_file: "xpcshell/head.js",
-          }
+                  diagnostic: _exception_message(e) + " - See following stack:",
-          else {
+                  stack: _format_exception_stack(e.stack)});
-            dump("\n");
+          } else {
+            _log("javascript_error",
+                 {source_file: "xpcshell/head.js",
+                  diagnostic: _exception_message(e)});
           }
           _do_quit();
         }
@@ -482,27 +517,25 @@ function do_throw(error, stack) {
   else if (error.fileName)
     filename = error.fileName;
 
-  _dump_message_with_stack("TEST-UNEXPECTED-FAIL | " + filename + " | ", error, stack);
+  _log_message_with_stack("test_unexpected_fail",
+                          error, stack, filename);
 
   _passed = false;
   _do_quit();
   throw Components.results.NS_ERROR_ABORT;
 }
 
-function _dump_stack(stack) {
+function _format_stack(stack) {
   if (stack instanceof Components.interfaces.nsIStackFrame) {
+    let stack_msg = "";
     let frame = stack;
     while (frame != null) {
-      _dump(frame + "\n");
+      stack_msg += frame + "\n";
       frame = frame.caller;
     }
+    return stack_msg;
   }
-  else if (typeof stack == "string") {
+  return "" + stack;
-    let stackLines = stack.split("\n");
-    for (let line of stackLines) {
-      _dump(line + "\n");
-    }
-  }
 }
 
 function do_throw_todo(text, stack) {
@@ -510,9 +543,8 @@ function do_throw_todo(text, stack) {
     stack = Components.stack.caller;
 
   _passed = false;
-  _dump_message_with_stack("TEST-UNEXPECTED-PASS | " + stack.filename + " | ",
+  _log_message_with_stack("test_unexpected_pass",
-      text, stack);
+                          text, stack, stack.filename);
-
   _do_quit();
   throw Components.results.NS_ERROR_ABORT;
 }
@@ -540,11 +572,19 @@ function _exception_message(ex) {
   return "" + ex;
 }
 
-function _dump_message_with_stack(preamble, ex, stack) {
+function _log_message_with_stack(action, ex, stack, filename, text) {
-  _dump(preamble + _exception_message(ex) +
-      (stack ? " - see following stack:\n" : "\n"));
   if (stack) {
-    _dump_stack(stack);
+    _log(action,
+         {diagnostic: (text ? text : "") +
+                      _exception_message(ex) +
+                      " - See following stack:",
+          source_file: filename,
+          stack: _format_stack(stack)});
+  } else {
+    _log(action,
+         {diagnostic: (text ? text : "") +
+                      _exception_message(ex),
+          source_file: filename});
   }
 }
 
@@ -553,10 +593,8 @@ function do_report_unexpected_exception(ex, text) {
   text = text ? text + " - " : "";
 
   _passed = false;
-  _dump_message_with_stack("TEST-UNEXPECTED-FAIL | " + caller_stack.filename +
+  _log_message_with_stack("test_unexpected_fail", ex, ex.stack,
-        " | " + text + "Unexpected exception ",
+                          caller_stack.filename, text + "Unexpected exception ");
-        ex, ex.stack);
-
   _do_quit();
   throw Components.results.NS_ERROR_ABORT;
 }
@@ -565,9 +603,8 @@ function do_note_exception(ex, text) {
   var caller_stack = Components.stack.caller;
   text = text ? text + " - " : "";
 
-  _dump_message_with_stack("TEST-INFO | " + caller_stack.filename +
+  _log_message_with_stack("test_info", ex, ex.stack,
-        " | " + text + "Swallowed exception ",
+                          caller_stack.filename, text + "Swallowed exception ");
-        ex, ex.stack);
 }
 
 function _do_check_neq(left, right, stack, todo) {
@@ -599,14 +636,22 @@ function do_report_result(passed, text, stack, todo) {
       do_throw_todo(text, stack);
     } else {
       ++_passedChecks;
-      _dump("TEST-PASS | " + stack.filename + " | [" + stack.name + " : " +
+      _log("test_pass",
-            stack.lineNumber + "] " + text + "\n");
+           {source_file: stack.filename,
+            test_name: stack.name,
+            line_number: stack.lineNumber,
+            diagnostic: "[" + stack.name + " : " + stack.lineNumber + "] " +
+                        text + "\n"});
     }
   } else {
     if (todo) {
       ++_todoChecks;
-      _dump("TEST-KNOWN-FAIL | " + stack.filename + " | [" + stack.name +
+      _log("test_known_fail",
-            " : " + stack.lineNumber + "] " + text +"\n");
+           {source_file: stack.filename,
+            test_name: stack.name,
+            line_number: stack.lineNumber,
+            diagnostic: "[" + stack.name + " : " + stack.lineNumber + "] " +
+                        text + "\n"});
     } else {
       do_throw(text, stack);
     }
@@ -826,14 +871,17 @@ function format_pattern_match_failure(diagnosis, indent="") {
 function do_test_pending(aName) {
   ++_tests_pending;
 
-  _dump("TEST-INFO | (xpcshell/head.js) | test" + (aName ? " " + aName : "") +
+  _log("test_pending",
-         " pending (" + _tests_pending + ")\n");
+       {_message: "TEST-INFO | (xpcshell/head.js) | test" +
+                  (aName ? " " + aName : "") +
+                  " pending (" + _tests_pending + ")\n"});
 }
 
 function do_test_finished(aName) {
-  _dump("TEST-INFO | (xpcshell/head.js) | test" + (aName ? " " + aName : "") +
+  _log("test_finish",
-         " finished (" + _tests_pending + ")\n");
+       {_message: "TEST-INFO | (xpcshell/head.js) | test" +
-
+                  (aName ? " " + aName : "") +
+                  " finished (" + _tests_pending + ")\n"});
   if (--_tests_pending == 0)
     _do_quit();
 }
@@ -858,9 +906,12 @@ function do_get_file(path, allowNonexistent) {
       // Not using do_throw(): caller will continue.
       _passed = false;
       var stack = Components.stack.caller;
-      _dump("TEST-UNEXPECTED-FAIL | " + stack.filename + " | [" +
+      _log("test_unexpected_fail",
-            stack.name + " : " + stack.lineNumber + "] " + lf.path +
+           {source_file: stack.filename,
-            " does not exist\n");
+            test_name: stack.name,
+            line_number: stack.lineNumber,
+            diagnostic: "[" + stack.name + " : " + stack.lineNumber + "] " +
+                        lf.path + " does not exist\n"});
     }
 
     return lf;
@@ -960,7 +1011,9 @@ function do_get_tempdir() {
  */
 function do_get_profile() {
   if (!runningInParent) {
-    _dump("TEST-INFO | (xpcshell/head.js) | Ignoring profile creation from child process.\n");
+    _log("test_info",
+         {_message: "TEST-INFO | (xpcshell/head.js) | Ignoring profile creation from child process.\n"});
+
     return null;
   }
 
@@ -1058,7 +1111,6 @@ function do_load_child_test_harness()
   }
 
   command += " load(_HEAD_JS_PATH);";
-
   sendCommand(command);
 }
 
@@ -1083,9 +1135,9 @@ function run_test_in_child(testFile, optionalCallback)
 
   var testPath = do_get_file(testFile).path.replace(/\\/g, "/");
   do_test_pending("run in child");
-  sendCommand("_dump('CHILD-TEST-STARTED'); "
+  sendCommand("_log('child_test_start', {_message: 'CHILD-TEST-STARTED'}); "
               + "const _TEST_FILE=['" + testPath + "']; _execute_test(); "
-              + "_dump('CHILD-TEST-COMPLETED');", 
+              + "_log('child_test_end', {_message: 'CHILD-TEST-COMPLETED'});",
               callback);
 }
 

testing/xpcshell/runxpcshelltests.py

@@ -5,20 +5,25 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import copy
-import re, sys, os, os.path, logging, shutil, math, time, traceback
+import json
+import math
+import os
+import os.path
+import random
+import shutil
+import signal
+import socket
+import sys
+import time
+import traceback
 import xml.dom.minidom
 from collections import deque
 from distutils import dir_util
-from glob import glob
 from multiprocessing import cpu_count
 from optparse import OptionParser
 from subprocess import Popen, PIPE, STDOUT
 from tempfile import mkdtemp, gettempdir
 from threading import Timer, Thread, Event, RLock
-import random
-import signal
-import socket
-import time
 
 try:
     import psutil
@@ -40,6 +45,18 @@ HARNESS_TIMEOUT = 5 * 60
 # benchmarking on tbpl revealed that this works best for now
 NUM_THREADS = int(cpu_count() * 4)
 
+FAILURE_ACTIONS = set(['test_unexpected_fail',
+                       'test_unexpected_pass',
+                       'javascript_error'])
+ACTION_STRINGS = {
+    "test_unexpected_fail": "TEST-UNEXPECTED-FAIL",
+    "test_known_fail": "TEST-KNOWN-FAIL",
+    "test_unexpected_pass": "TEST-UNEXPECTED-PASS",
+    "javascript_error": "TEST-UNEXPECTED-FAIL",
+    "test_pass": "TEST-PASS",
+    "test_info": "TEST-INFO"
+}
+
 # --------------------------------------------------------------
 # TODO: this is a hack for mozbase without virtualenv, remove with bug 849900
 #
@@ -110,6 +127,9 @@ class XPCShellTestThread(Thread):
         self.todoCount = 0
         self.failCount = 0
 
+        self.output_lines = []
+        self.has_failure_output = False
+
         # event from main thread to signal work done
         self.event = event
 
@@ -329,15 +349,7 @@ class XPCShellTestThread(Thread):
         if self.pluginsDir:
             self.xpcsCmd.extend(['-p', self.pluginsDir])
 
-    def print_stdout(self, stdout):
+    def cleanupDir(self, directory, name, xunit_result):
-        """Print stdout line-by-line to avoid overflowing buffers."""
-        self.log.info(">>>>>>>")
-        if stdout:
-            for line in stdout.splitlines():
-                self.log.info(line)
-        self.log.info("<<<<<<<")
-
-    def cleanupDir(self, directory, name, stdout, xunit_result):
         TRY_LIMIT = 25 # up to TRY_LIMIT attempts (one every second), because
                        # the Windows filesystem is slow to react to the changes
         try_count = 0
@@ -364,8 +376,8 @@ class XPCShellTestThread(Thread):
         with LOG_MUTEX:
             message = "TEST-UNEXPECTED-FAIL | %s | Failed to clean up directory: %s" % (name, sys.exc_info()[1])
             self.log.error(message)
-            self.print_stdout(stdout)
+            self.log_output(self.output_lines)
-            self.print_stdout(traceback.format_exc())
+            self.log_output(traceback.format_exc())
 
         self.failCount += 1
         xunit_result["passed"] = False
@@ -375,6 +387,81 @@ class XPCShellTestThread(Thread):
             "text": "%s\n%s" % (stdout, traceback.format_exc())
         }
 
+    def append_message_from_line(self, line):
+        """Given a line of raw output, convert to message and append to
+        output buffer."""
+        if isinstance(line, basestring):
+            # This function has received unstructured output.
+            if line:
+                self.output_lines.append(line)
+                if 'TEST-UNEXPECTED-' in line:
+                    self.has_failure_output = True
+            return
+
+        msg = ['%s: ' % line['process'] if 'process' in line else '']
+
+        # Each call to the logger in head.js either specified '_message'
+        # or both 'source_file' and 'diagnostic'. If either of these are
+        # missing, they ended up being undefined as a result of the way
+        # the test was run.
+        if '_message' in line:
+            msg.append(line['_message'])
+        else:
+            msg.append('%s | %s | %s' % (ACTION_STRINGS[line['action']],
+                                         line.get('source_file', 'undefined'),
+                                         line.get('diagnostic', 'undefined')))
+
+        msg.append('\n%s' % line['stack'] if 'stack' in line else '')
+        self.output_lines.append(''.join(msg))
+
+    def parse_output(self, output):
+        """Parses process output for structured messages and saves output as it is
+        read. Sets self.has_failure_output in case of evidence of a failure"""
+        seen_proc_start = False
+        seen_proc_end = False
+        self.output_lines = []
+        for line_string in output.splitlines():
+            try:
+                line_object = json.loads(line_string)
+                if not isinstance(line_object, dict):
+                    self.append_message_from_line(line_string)
+                    continue
+            except ValueError:
+                self.append_message_from_line(line_string)
+                continue
+
+            if 'action' not in line_object:
+                # In case a test outputs something that happens to be valid
+                # JSON object.
+                self.append_message_from_line(line_string)
+                continue
+
+            action = line_object['action']
+            self.append_message_from_line(line_object)
+
+            if action in FAILURE_ACTIONS:
+                self.has_failure_output = True
+
+            elif action == 'child_test_start':
+                seen_proc_start = True
+            elif action == 'child_test_end':
+                seen_proc_end = True
+
+        if seen_proc_start and not seen_proc_end:
+            self.has_failure_output = True
+
+    def log_output(self, output):
+        """Prints given output line-by-line to avoid overflowing buffers."""
+        self.log.info(">>>>>>>")
+        if output:
+            if isinstance(output, basestring):
+                output = output.splitlines()
+            for part in output:
+                # For multi-line output, such as a stack trace
+                for line in part.splitlines():
+                    self.log.info(line)
+        self.log.info("<<<<<<<")
+
     def run_test(self):
         """Run an individual xpcshell test."""
         global gotSIGINT
@@ -466,18 +553,9 @@ class XPCShellTestThread(Thread):
             if testTimer:
                 testTimer.cancel()
 
-            result = not ((self.getReturnCode(proc) != 0) or
+            self.parse_output(stdout)
-                          # if do_throw or do_check failed
+            result = not (self.has_failure_output or
-                          (stdout and re.search("^((parent|child): )?TEST-UNEXPECTED-",
+                          (self.getReturnCode(proc) != 0))
-                                                stdout, re.MULTILINE)) or
-                          # if syntax error in xpcshell file
-                          (stdout and re.search(": SyntaxError:", stdout,
-                                                re.MULTILINE)) or
-                          # if e10s test started but never finished (child process crash)
-                          (stdout and re.search("^child: CHILD-TEST-STARTED",
-                                                stdout, re.MULTILINE)
-                                  and not re.search("^child: CHILD-TEST-COMPLETED",
-                                                    stdout, re.MULTILINE)))
 
             if result != expected:
                 failureType = "TEST-UNEXPECTED-%s" % ("FAIL" if expected else "PASS")
@@ -486,7 +564,7 @@ class XPCShellTestThread(Thread):
 
                 with LOG_MUTEX:
                     self.log.error(message)
-                    self.print_stdout(stdout)
+                    self.log_output(self.output_lines)
 
                 self.failCount += 1
                 self.xunit_result["passed"] = False
@@ -504,7 +582,7 @@ class XPCShellTestThread(Thread):
                 with LOG_MUTEX:
                     self.log.info("TEST-%s | %s | test passed (time: %.3fms)" % ("PASS" if expected else "KNOWN-FAIL", name, timeTaken))
                     if self.verbose:
-                        self.print_stdout(stdout)
+                        self.log_output(self.output_lines)
 
                 self.xunit_result["passed"] = True
 
@@ -534,7 +612,7 @@ class XPCShellTestThread(Thread):
                 with LOG_MUTEX:
                     message = "TEST-UNEXPECTED-FAIL | %s | Process still running after test!" % name
                     self.log.error(message)
-                    self.print_stdout(stdout)
+                    self.log_output(self.output_lines)
 
                 self.failCount = 1
                 self.xunit_result["passed"] = False
@@ -549,12 +627,12 @@ class XPCShellTestThread(Thread):
             # We don't want to delete the profile when running check-interactive
             # or check-one.
             if self.profileDir and not self.interactive and not self.singleFile:
-                self.cleanupDir(self.profileDir, name, stdout, self.xunit_result)
+                self.cleanupDir(self.profileDir, name, self.xunit_result)
 
-            self.cleanupDir(self.tempDir, name, stdout, self.xunit_result)
+            self.cleanupDir(self.tempDir, name, self.xunit_result)
 
             if self.pluginsDir:
-                self.cleanupDir(self.pluginsDir, name, stdout, self.xunit_result)
+                self.cleanupDir(self.pluginsDir, name, self.xunit_result)
 
         if gotSIGINT:
             self.xunit_result["passed"] = False

testing/xpcshell/selftest.py

@@ -64,7 +64,7 @@ function run_test () { run_next_test(); }
 add_test(function test_child_simple () {
   do_test_pending("hang test");
   do_load_child_test_harness();
-  sendCommand("_dump('CHILD-TEST-STARTED'); " +
+  sendCommand("_log('child_test_start', {_message: 'CHILD-TEST-STARTED'}); " +
               + "const _TEST_FILE=['test_pass.js']; _execute_test(); ",
               do_test_finished);
   run_next_test();