diff --git a/testing/xpcshell/head.js b/testing/xpcshell/head.js index c8e7ff328e22..6da236eba5df 100644 --- a/testing/xpcshell/head.js +++ b/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) { - stack.split("\n").forEach(function(frame) { - if (!frame) - return; - // frame is of the form "fname(args)@file:line" - let frame_regexp = new RegExp("(.*)\\(.*\\)@(.*):(\\d*)", "g"); - let parts = frame_regexp.exec(frame); - if (parts) - dump("JS frame :: " + parts[2] + " :: " + (parts[1] ? parts[1] : "anonymous") - + " :: line " + parts[3] + "\n"); - else /* Could be a -e (command line string) style location. */ - dump("JS frame :: " + frame + "\n"); - }); +function _format_exception_stack(stack) { + // frame is of the form "fname(args)@file:line" + let frame_regexp = new RegExp("(.*)\\(.*\\)@(.*):(\\d*)", "g"); + return stack.split("\n").reduce(function(stack_msg, frame) { + if (frame) { + let parts = frame_regexp.exec(frame); + if (parts) { + return stack_msg + "JS frame :: " + parts[2] + " :: " + + (parts[1] ? parts[1] : "anonymous") + + " :: line " + parts[3] + "\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"); - _dump_exception_stack(e.stack); - } - else { - _dump(msg + "\n"); + msgObject.diagnostic += " - See following stack:\n"; + msgObject.stack = _format_exception_stack(e.stack); } + _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 + " (+ " + - _falsePassedChecks + ") check(s) passed\n"); - _dump("TEST-INFO | (xpcshell/head.js) | " + _todoChecks + - " check(s) todo\n"); + _log("test_pass", + {_message: "TEST-PASS | (xpcshell/head.js) | " + truePassedChecks + " (+ " + + _falsePassedChecks + ") check(s) passed\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"); - _dump_exception_stack(e.stack); - } - else { - dump("\n"); + _log("javascript_error", + {source_file: "xpcshell/head.js", + diagnostic: _exception_message(e) + " - See following stack:", + stack: _format_exception_stack(e.stack)}); + } 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") { - let stackLines = stack.split("\n"); - for (let line of stackLines) { - _dump(line + "\n"); - } - } + return "" + stack; } 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 + " | ", - text, stack); - + _log_message_with_stack("test_unexpected_pass", + 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) { - _dump(preamble + _exception_message(ex) + - (stack ? " - see following stack:\n" : "\n")); +function _log_message_with_stack(action, ex, stack, filename, text) { 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 + - " | " + text + "Unexpected exception ", - ex, ex.stack); - + _log_message_with_stack("test_unexpected_fail", ex, ex.stack, + caller_stack.filename, text + "Unexpected exception "); _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 + - " | " + text + "Swallowed exception ", - ex, ex.stack); + _log_message_with_stack("test_info", ex, ex.stack, + caller_stack.filename, text + "Swallowed exception "); } 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 + " : " + - stack.lineNumber + "] " + text + "\n"); + _log("test_pass", + {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 + - " : " + stack.lineNumber + "] " + text +"\n"); + _log("test_known_fail", + {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 : "") + - " pending (" + _tests_pending + ")\n"); + _log("test_pending", + {_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 : "") + - " finished (" + _tests_pending + ")\n"); - + _log("test_finish", + {_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 + " | [" + - stack.name + " : " + stack.lineNumber + "] " + lf.path + - " does not exist\n"); + _log("test_unexpected_fail", + {source_file: stack.filename, + 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); } diff --git a/testing/xpcshell/runxpcshelltests.py b/testing/xpcshell/runxpcshelltests.py index a7edcc5aff46..efc4c90ff86e 100644 --- a/testing/xpcshell/runxpcshelltests.py +++ b/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): - """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): + def cleanupDir(self, directory, name, 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.print_stdout(traceback.format_exc()) + self.log_output(self.output_lines) + 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 - # if do_throw or do_check failed - (stdout and re.search("^((parent|child): )?TEST-UNEXPECTED-", - 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))) + self.parse_output(stdout) + result = not (self.has_failure_output or + (self.getReturnCode(proc) != 0)) 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 diff --git a/testing/xpcshell/selftest.py b/testing/xpcshell/selftest.py index afefd01b0fdb..b904f3888376 100644 --- a/testing/xpcshell/selftest.py +++ b/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();