From 316b0eb1ef102adc55f4dd0afa067a8feac577f5 Mon Sep 17 00:00:00 2001 From: Ted Mielczarek Date: Tue, 13 Oct 2009 16:56:24 -0400 Subject: [PATCH] bug 501034 - add hang detection + breakpad triggering to automation.py. r=Waldo --HG-- extra : rebase_source : 088eeeb0c3135d1048dca08f3639642a90b2eab2 --- build/automation-build.mk | 6 +++ build/automation.py.in | 64 +++++++++++++++++++++++++++--- build/pgo/profileserver.py.in | 5 ++- layout/tools/reftest/runreftest.py | 5 ++- testing/mochitest/runtests.py.in | 9 ++++- 5 files changed, 79 insertions(+), 10 deletions(-) diff --git a/build/automation-build.mk b/build/automation-build.mk index 50c11fd44de..598977f7ab3 100644 --- a/build/automation-build.mk +++ b/build/automation-build.mk @@ -68,6 +68,12 @@ else AUTOMATION_PPARGS += -DIS_DEBUG_BUILD=0 endif +ifdef MOZ_CRASHREPORTER +AUTOMATION_PPARGS += -DCRASHREPORTER=1 +else +AUTOMATION_PPARGS += -DCRASHREPORTER=0 +endif + $(CURDIR)/automationutils.py: $(MOZILLA_DIR)/build/automationutils.py $(INSTALL) $< . diff --git a/build/automation.py.in b/build/automation.py.in index fbba820de8c..66c7c50257f 100644 --- a/build/automation.py.in +++ b/build/automation.py.in @@ -43,6 +43,7 @@ import itertools import logging import os import re +import select import shutil import signal import subprocess @@ -72,8 +73,12 @@ __all__ = [ "environment", "IS_TEST_BUILD", "IS_DEBUG_BUILD", + "DEFAULT_TIMEOUT", ] +# timeout, in seconds +DEFAULT_TIMEOUT = 60.0 + # These are generated in mozilla/build/Makefile.in #expand DIST_BIN = __XPC_BIN_PATH__ #expand IS_WIN32 = len("__WIN32__") != 0 @@ -94,6 +99,7 @@ UNIXISH = not IS_WIN32 and not IS_MAC #expand CERTS_SRC_DIR = __CERTS_SRC_DIR__ #expand IS_TEST_BUILD = __IS_TEST_BUILD__ #expand IS_DEBUG_BUILD = __IS_DEBUG_BUILD__ +#expand CRASHREPORTER = __CRASHREPORTER__ == 1 ########### # LOGGING # @@ -434,6 +440,40 @@ def environment(env = None, xrePath = DIST_BIN, crashreporter = True): env['GNOME_DISABLE_CRASH_DIALOG'] = "1" return env +if IS_WIN32: + import ctypes, time, msvcrt + PeekNamedPipe = ctypes.windll.kernel32.PeekNamedPipe + GetLastError = ctypes.windll.kernel32.GetLastError + def readWithTimeout(f, timeout): + """Try to read a line of output from the file object |f|. + |f| must be a pipe, like the |stdout| member of a subprocess.Popen + object created with stdout=PIPE. If no output + is received within |timeout| seconds, return a blank line. + Returns a tuple (line, did_timeout), where |did_timeout| is True + if the read timed out, and False otherwise.""" + x = msvcrt.get_osfhandle(f.fileno()) + l = ctypes.c_long() + buf = ctypes.create_string_buffer('', 1024) + done = time.time() + timeout + while time.time() < done: + if PeekNamedPipe(x, buf, len(buf), None, ctypes.byref(l), None) == 0: + err = GetLastError() + if err == 38 or err == 109: # ERROR_HANDLE_EOF || ERROR_BROKEN_PIPE + return ('', False) + if (l > 0 and '\n' in buf.value): + return (f.readline(), False) + time.sleep(0.1) + return ('', True) +else: + def readWithTimeout(f, timeout): + """Try to read a line of output from the file object |f|. If no output + is received within |timeout| seconds, return a blank line. + Returns a tuple (line, did_timeout), where |did_timeout| is True + if the read timed out, and False otherwise.""" + (r, w, e) = select.select([f], [], [], timeout) + if len(r) == 0: + return ('', True) + return (f.readline(), False) ############### # RUN THE APP # @@ -442,7 +482,8 @@ def environment(env = None, xrePath = DIST_BIN, crashreporter = True): def runApp(testURL, env, app, profileDir, extraArgs, runSSLTunnel = False, utilityPath = DIST_BIN, xrePath = DIST_BIN, certPath = CERTS_SRC_DIR, - debuggerInfo = None, symbolsPath = None): + debuggerInfo = None, symbolsPath = None, + timeout = DEFAULT_TIMEOUT): "Run the app, log the duration it took to execute, return the status code." # copy env so we don't munge the caller's environment @@ -506,6 +547,7 @@ def runApp(testURL, env, app, profileDir, extraArgs, log.info("INFO | automation.py | Application pid: %d", proc.pid) stackFixerProcess = None + didTimeout = False if outputPipe is None: log.info("TEST-INFO: Not logging stdout or stderr due to debugger connection") else: @@ -520,17 +562,27 @@ def runApp(testURL, env, app, profileDir, extraArgs, stackFixerProcess = Process([PERL, os.path.join(utilityPath, stackFixerCommand)], stdin=logsource, stdout=subprocess.PIPE) logsource = stackFixerProcess.stdout - line = logsource.readline() - while line != "": + (line, didTimeout) = readWithTimeout(logsource, timeout) + while line != "" and not didTimeout: log.info(line.rstrip()) - line = logsource.readline() + (line, didTimeout) = readWithTimeout(logsource, timeout) + if didTimeout: + log.info("TEST-UNEXPECTED-FAIL | automation.py | application timed out after %d seconds with no output", int(timeout)) + if CRASHREPORTER: + if UNIXISH: + os.kill(proc.pid, signal.SIGSEGV) + else: + #TODO: kill the process such that it triggers Breakpad + proc.kill() + else: + proc.kill() status = proc.wait() - if status != 0: + if status != 0 and not didTimeout: log.info("TEST-UNEXPECTED-FAIL | automation.py | Exited with code %d during test run", status) if stackFixerProcess is not None: status = stackFixerProcess.wait() - if status != 0: + if status != 0 and not didTimeout: log.info("TEST-UNEXPECTED-FAIL | automation.py | Stack fixer process exited with code %d during test run", status) log.info("INFO | automation.py | Application ran for: %s", str(datetime.now() - startTime)) diff --git a/build/pgo/profileserver.py.in b/build/pgo/profileserver.py.in index d22703c2957..e4f8886aace 100644 --- a/build/pgo/profileserver.py.in +++ b/build/pgo/profileserver.py.in @@ -68,5 +68,8 @@ if __name__ == '__main__': url = "http://localhost:%d/index.html" % PORT appPath = os.path.join(SCRIPT_DIR, automation.DEFAULT_APP) - status = automation.runApp(url, browserEnv, appPath, PROFILE_DIRECTORY, {}) + status = automation.runApp(url, browserEnv, appPath, PROFILE_DIRECTORY, {}, + # the profiling HTML doesn't output anything, + # so let's just ignore this for now. + timeout = None) sys.exit(status) diff --git a/layout/tools/reftest/runreftest.py b/layout/tools/reftest/runreftest.py index 915a144a6bd..1b70971458a 100644 --- a/layout/tools/reftest/runreftest.py +++ b/layout/tools/reftest/runreftest.py @@ -173,7 +173,10 @@ Are you executing $objdir/_tests/reftest/runreftest.py?""" \ utilityPath = options.utilityPath, xrePath=options.xrePath, debuggerInfo=debuggerInfo, - symbolsPath=options.symbolsPath) + symbolsPath=options.symbolsPath, + # give the JS harness 30 seconds to deal + # with its own timeouts + timeout=options.timeout + 30.0) processLeakLog(leakLogFile, options.leakThreshold) automation.log.info("\nREFTEST INFO | runreftest.py | Running tests: end.") finally: diff --git a/testing/mochitest/runtests.py.in b/testing/mochitest/runtests.py.in index f3f5fed5e37..e15b8d4f0d1 100644 --- a/testing/mochitest/runtests.py.in +++ b/testing/mochitest/runtests.py.in @@ -455,7 +455,11 @@ Are you executing $objdir/_tests/testing/mochitest/runtests.py?""" if os.path.exists(LEAK_REPORT_FILE): os.remove(LEAK_REPORT_FILE) - # then again to actually run reftest + # then again to actually run mochitest + # don't use a timeout if we're not auto-running + #XXX: use the value from --timeout when bug 521130 lands, for now + # use the Mochitest JS harness's timeout + 30 seconds + timeout = options.autorun and 330.0 or None automation.log.info("INFO | runtests.py | Running tests: start.\n") status = automation.runApp(testURL, browserEnv, options.app, PROFILE_DIRECTORY, options.browserArgs, @@ -464,7 +468,8 @@ Are you executing $objdir/_tests/testing/mochitest/runtests.py?""" xrePath = options.xrePath, certPath=options.certPath, debuggerInfo=debuggerInfo, - symbolsPath=options.symbolsPath) + symbolsPath=options.symbolsPath, + timeout = timeout) # Server's no longer needed, and perhaps more importantly, anything it might # spew to console shouldn't disrupt the leak information table we print next.