def test_23(self): "test hitting log size limit" ffp = FFPuppet() self.addCleanup(ffp.clean_up) with open(self.tmpfn, 'w') as prefs: prefs.write('//fftest_big_log\n') limit = 0x100000 # 1MB ffp.launch(TESTFF_BIN, prefs_js=self.tmpfn, log_limit=limit) self.assertIsNotNone(ffp.wait(10)) self.assertIsNotNone(ffp.returncode) ffp.close() self.assertEqual(ffp.reason, ffp.RC_WORKER) self.assertIsNotNone(ffp.returncode) ffp.save_logs(self.logs) total_size = 0 for fname in os.listdir(self.logs): self.assertIn(fname, [ "log_ffp_worker_log_size_limiter.txt", "log_stderr.txt", "log_stdout.txt" ]) total_size += os.stat(os.path.join(self.logs, fname)).st_size self.assertLess(limit, total_size) with open( os.path.join(self.logs, "log_ffp_worker_log_size_limiter.txt"), "r") as log_fp: self.assertIn("LOG_SIZE_LIMIT_EXCEEDED", log_fp.read())
def test_17(self): "test launching with gdb" if not sys.platform.startswith("linux"): with self.assertRaisesRegex(EnvironmentError, "GDB is only supported on Linux"): FFPuppet(use_gdb=True) else: ffp = FFPuppet(use_gdb=True) self.addCleanup(ffp.clean_up) bin_path = str( subprocess.check_output(["which", "echo"]).strip().decode("ascii")) # launch will fail b/c 'echo' will exit right away but that's fine with self.assertRaisesRegex(LaunchError, "Failure during browser startup"): self.assertEqual(ffp.launch(bin_path), 0) ffp.close() ffp.save_logs(self.logs) with open(os.path.join(self.logs, "log_stdout.txt"), "rb") as log_fp: log_data = log_fp.read() # verify GDB ran and executed the script self.assertRegex( log_data, br"[Inferior \d+ (process \d+) exited with code \d+]") self.assertRegex(log_data, br"\+quit_with_code")
def test_08(self): "test clone_log()" ffp = FFPuppet() self.addCleanup(ffp.clean_up) self.assertIsNone(ffp.clone_log("stdout", target_file=self.tmpfn)) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) ffp.wait(0.25) # wait for log prints # make sure logs are available self.assertEqual(ffp.clone_log("stdout", target_file=self.tmpfn), self.tmpfn) with open(self.tmpfn, "rb") as tmpfp: orig = tmpfp.read() self.assertGreater(len(orig), 5) self.assertEqual( ffp.clone_log("stdout", target_file=self.tmpfn, offset=5), self.tmpfn) with open(self.tmpfn, "rb") as tmpfp: self.assertEqual(tmpfp.read(), orig[5:]) # grab log without giving a target file name rnd_log = ffp.clone_log("stdout") self.assertIsNotNone(rnd_log) try: ffp.close() # make sure logs are available self.assertEqual(ffp.clone_log("stdout", target_file=self.tmpfn), self.tmpfn) with open(self.tmpfn, "rb") as tmpfp: self.assertTrue(tmpfp.read().startswith(orig)) finally: if os.path.isfile(rnd_log): os.remove(rnd_log) # verify clean_up() removed the logs ffp.clean_up() self.assertIsNone(ffp.clone_log("stdout", target_file=self.tmpfn))
def test_04(self): "test logging" ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.close() ffp.save_logs(os.path.join(self.logs, "no_logs")) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) ffp.wait(0.25) # wait for log prints ffp.close() self.assertTrue(ffp._logs.closed) # pylint: disable=protected-access log_ids = ffp.available_logs() self.assertEqual(len(log_ids), 2) self.assertIn("stderr", log_ids) self.assertIn("stdout", log_ids) log_dir = os.path.join(self.logs, "some_dir") # nonexistent directory ffp.save_logs(log_dir) self.assertTrue(os.path.isdir(log_dir)) log_list = os.listdir(log_dir) self.assertIn("log_stderr.txt", log_list) self.assertIn("log_stdout.txt", log_list) with open(os.path.join(log_dir, "log_stdout.txt"), "r") as log_fp: self.assertIn("url: http://", log_fp.read().strip()) for fname in log_list: with open(os.path.join(log_dir, fname)) as log_fp: log_data = log_fp.read().splitlines() if fname.startswith("log_stderr"): self.assertEqual(len(log_data), 3) self.assertTrue(log_data[0].startswith('[ffpuppet] Launch command:')) self.assertTrue(log_data[-1].startswith('[ffpuppet] Exit code:')) # exit code differs between platforms elif fname.startswith("log_stdout"): self.assertEqual(log_data[0], "hello world") else: raise AssertionError("Unknown log file %r" % fname)
def test_25(self): "test multiple minidumps" ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN) md_dir = os.path.join(ffp.profile, "minidumps") if not os.path.isdir(md_dir): os.mkdir(md_dir) ffp._last_bin_path = ffp.profile # pylint: disable=protected-access sym_dir = os.path.join(ffp.profile, "symbols") # needs to exist to satisfy a check if not os.path.isdir(sym_dir): os.mkdir(sym_dir) # create "test.dmp" files with open(os.path.join(md_dir, "test1.dmp"), "w") as out_fp: out_fp.write("1a\n1b") with open(os.path.join(md_dir, "test2.dmp"), "w") as out_fp: out_fp.write("2a\n2b") with open(os.path.join(md_dir, "test3.dmp"), "w") as out_fp: out_fp.write("3a\n3b") self.assertFalse(ffp.is_healthy()) # process .dmp file ffp.close() ffp.save_logs(self.logs) logs = os.listdir(self.logs) self.assertIn("log_minidump_01.txt", logs) self.assertIn("log_minidump_02.txt", logs) self.assertIn("log_minidump_03.txt", logs)
def test_29(self): "test rmtree error handler" # normal profile creation # - just create a puppet, write a readonly file in its profile, then call close() ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN) ro_file = os.path.join(ffp.profile, "read-only-test.txt") with open(ro_file, "w"): pass os.chmod(ro_file, stat.S_IREAD) ffp.close() self.assertFalse(os.path.isfile(ro_file)) ffp.clean_up() # use template profile that contains a readonly file prf_dir = tempfile.mkdtemp() self.addCleanup(shutil.rmtree, prf_dir, onerror=onerror) ro_file = os.path.join(prf_dir, "read-only.txt") with open(ro_file, "w"): pass os.chmod(ro_file, stat.S_IREAD) ffp = FFPuppet(use_profile=prf_dir) self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN) working_prf = ffp.profile self.assertTrue(os.path.isdir(working_prf)) ffp.close() self.assertFalse(os.path.isdir(working_prf))
def test_11(self): "test abort tokens" with open(self.tmpfn, 'w') as prefs: prefs.write('//fftest_soft_assert\n') ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.add_abort_token(re.compile(r"TEST\dREGEX\.+")) with self.assertRaisesRegex( TypeError, "Expecting 'str' or 're._pattern_type' got: 'NoneType'"): ffp.add_abort_token(None) ffp.add_abort_token("###!!! ASSERTION:") ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr(), prefs_js=self.tmpfn) self.assertIsNotNone(ffp.wait(10)) ffp.close() self.assertEqual(ffp.reason, ffp.RC_WORKER) self.assertIsNotNone(ffp.returncode) self.assertEqual(len(ffp.available_logs()), 3) ffp.save_logs(self.logs) worker_log = os.path.join(self.logs, "log_ffp_worker_log_scanner.txt") self.assertTrue(os.path.isfile(worker_log)) with open(worker_log, "rb") as log_fp: self.assertIn(b"TOKEN_LOCATED", log_fp.read())
def test_05(self): "test get_pid()" ffp = FFPuppet() self.addCleanup(ffp.clean_up) self.assertIsNone(ffp.get_pid()) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) self.assertGreater(ffp.get_pid(), 0) ffp.close() self.assertIsNone(ffp.get_pid())
def test_06(self): "test is_running()" ffp = FFPuppet() self.addCleanup(ffp.clean_up) self.assertFalse(ffp.is_running()) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) self.assertTrue(ffp.is_running()) ffp.close() self.assertFalse(ffp.is_running()) self.assertFalse(ffp.is_running()) # call 2x
def test_10(self): "test calling launch() multiple times" ffp = FFPuppet() self.addCleanup(ffp.clean_up) for _ in range(10): ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) ffp.close() # call 2x without calling close() ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) with self.assertRaisesRegex(LaunchError, "Process is already running"): ffp.launch(TESTFF_BIN) ffp.close()
def test_24(self): "test collecting and cleaning up ASan logs" ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN) test_logs = list() asan_prefix = os.path.join(ffp._logs.working_path, ffp._logs.LOG_ASAN_PREFIX) # pylint: disable=protected-access for i in range(3): test_logs.append(".".join([asan_prefix, str(i)])) # small log with nothing interesting with open(test_logs[0], "w") as log_fp: log_fp.write("SHORT LOG\n") log_fp.write("filler line") # crash on another thread with open(test_logs[1], "w") as log_fp: log_fp.write("GOOD LOG\n") log_fp.write( "==70811==ERROR: AddressSanitizer: SEGV on unknown address 0x00000BADF00D" ) log_fp.write( " (pc 0x7f4c0bb54c67 bp 0x7f4c07bea380 sp 0x7f4c07bea360 T0)\n" ) # must be 2nd line for _ in range(4): # pad out to 6 lines log_fp.write("filler line\n") # child log that should be ignored (created when parent crashes) with open(test_logs[2], "w") as log_fp: log_fp.write("BAD LOG\n") log_fp.write( "==70811==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000" ) log_fp.write( " (pc 0x7f4c0bb54c67 bp 0x7f4c07bea380 sp 0x7f4c07bea360 T2)\n" ) # must be 2nd line for _ in range(4): # pad out to 6 lines log_fp.write("filler line\n") self.assertFalse(ffp.is_healthy()) self.assertTrue(ffp.is_running()) ffp.close() ffp.save_logs(self.logs) dir_list = os.listdir(self.logs) self.assertEqual(len(dir_list), 5) for fname in dir_list: if not fname.startswith("log_ffp_asan_"): self.assertIn(fname, ["log_stderr.txt", "log_stdout.txt"]) continue with open(os.path.join(self.logs, fname), "r") as log_fp: self.assertIn(log_fp.readline(), ["BAD LOG\n", "GOOD LOG\n", "SHORT LOG\n"]) ffp.clean_up() for t_log in test_logs: self.assertFalse(os.path.isfile(t_log))
def test_21(self): "test log_length()" ffp = FFPuppet() self.addCleanup(ffp.clean_up) self.assertIsNone(ffp.log_length("INVALID")) self.assertIsNone(ffp.log_length("stderr")) ffp.launch(TESTFF_BIN) self.assertGreater(ffp.log_length("stderr"), 0) ffp.close() self.assertGreater(ffp.log_length("stderr"), 0) ffp.clean_up() # verify clean_up() removed the logs self.assertIsNone(ffp.log_length("stderr"))
def test_02(self): "test crash on start" ffp = FFPuppet() self.addCleanup(ffp.clean_up) with open(self.tmpfn, 'w') as prefs: prefs.write('//fftest_startup_crash\n') with self.assertRaisesRegex(BrowserTerminatedError, "Failure during browser startup"): ffp.launch(TESTFF_BIN, prefs_js=self.tmpfn) ffp.close() self.assertFalse(ffp.is_running()) # process should be gone self.assertEqual(ffp.launches, 0) self.assertEqual(ffp.reason, ffp.RC_ALERT)
def test_27(self): "test multiprocess target" with open(self.tmpfn, "w") as prefs_fp: prefs_fp.write("//fftest_multi_proc\n") ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN, prefs_js=self.tmpfn, location=self.tsrv.get_addr()) self.assertTrue(ffp.is_running()) self.assertIsNone(ffp.wait(0)) c_procs = Process(ffp.get_pid()).children() self.assertGreater(len(c_procs), 0) # terminate one of the processes c_procs[-1].terminate() ffp.close() self.assertFalse(ffp.is_running()) self.assertIsNone(ffp.wait(0))
def test_30(self): "test using a readonly prefs.js and extension" prefs = os.path.join(self.logs, "prefs.js") with open(prefs, "w"): pass os.chmod(prefs, stat.S_IREAD) ext = os.path.join(self.logs, "ext.xpi") with open(ext, "w"): pass os.chmod(ext, stat.S_IREAD) ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN, extension=ext, prefs_js=prefs) working_prf = ffp.profile ffp.close() self.assertFalse(os.path.isdir(working_prf))
def test_09(self): "test hitting memory limit" ffp = FFPuppet() self.addCleanup(ffp.clean_up) with open(self.tmpfn, 'w') as prefs: prefs.write('//fftest_memory\n') ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr(), prefs_js=self.tmpfn, memory_limit=0x100000) # 1MB self.assertIsNotNone(ffp.wait(30)) ffp.close() self.assertIsNotNone(ffp.returncode) self.assertEqual(ffp.reason, ffp.RC_WORKER) self.assertEqual(len(ffp.available_logs()), 3) ffp.save_logs(self.logs) worker_log = os.path.join(self.logs, "log_ffp_worker_memory_limiter.txt") self.assertTrue(os.path.isfile(worker_log)) with open(worker_log, "rb") as log_fp: self.assertIn(b"MEMORY_LIMIT_EXCEEDED", log_fp.read())
def test_03(self): "test hang on start" ffp = FFPuppet() default_timeout = ffp.LAUNCH_TIMEOUT_MIN try: ffp.LAUNCH_TIMEOUT_MIN = 1 self.addCleanup(ffp.clean_up) with open(self.tmpfn, 'w') as prefs: prefs.write('//fftest_startup_hang\n') start = time.time() with self.assertRaisesRegex(BrowserTimeoutError, "Launching browser timed out"): ffp.launch(TESTFF_BIN, prefs_js=self.tmpfn, launch_timeout=1) duration = time.time() - start ffp.close() self.assertEqual(ffp.reason, ffp.RC_CLOSED) self.assertGreater(duration, ffp.LAUNCH_TIMEOUT_MIN) self.assertLess(duration, 30) finally: ffp.LAUNCH_TIMEOUT_MIN = default_timeout
def test_01(self): "test basic launch and close" ffp = FFPuppet() self.addCleanup(ffp.clean_up) self.assertEqual(ffp.launches, 0) self.assertEqual(ffp.reason, ffp.RC_CLOSED) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) self.assertEqual(len(ffp._workers), 0) # pylint: disable=protected-access self.assertEqual(ffp.launches, 1) self.assertIsNone(ffp.wait(0)) self.assertTrue(ffp.is_running()) self.assertTrue(ffp.is_healthy()) self.assertIsNone(ffp.reason) ffp.close() self.assertEqual(ffp.reason, ffp.RC_CLOSED) self.assertIsNone(ffp._proc) # pylint: disable=protected-access self.assertFalse(ffp.is_running()) self.assertFalse(ffp.is_healthy()) self.assertIsNone(ffp.wait(10))
def test_19(self): "test launching with Valgrind" if not sys.platform.startswith("linux"): with self.assertRaisesRegex(EnvironmentError, "Valgrind is only supported on Linux"): FFPuppet(use_valgrind=True) else: ffp = FFPuppet(use_valgrind=True) self.addCleanup(ffp.clean_up) bin_path = str(subprocess.check_output(["which", "echo"]).strip().decode("ascii")) # launch will fail b/c 'echo' will exit right away but that's fine with self.assertRaisesRegex(LaunchError, "Failure during browser startup"): self.assertEqual(ffp.launch(bin_path), 0) ffp.close() ffp.save_logs(self.logs) with open(os.path.join(self.logs, "log_stderr.txt"), "rb") as log_fp: log_data = log_fp.read() # verify Valgrind ran and executed the script self.assertRegex(log_data, br"valgrind -q") self.assertRegex(log_data, br"\[ffpuppet\] Exit code: 0")
def test_07(self): "test wait()" ffp = FFPuppet() self.addCleanup(ffp.clean_up) # call when ffp._proc is None self.assertIsNone(ffp.wait()) ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) # call when ffp._proc is running self.assertTrue(ffp.is_running()) self.assertIsNone(ffp.wait(0)) ffp._terminate() # pylint: disable=protected-access # call when ffp._proc is not running self.assertFalse(ffp.is_running()) self.assertIsNotNone(ffp.wait(0)) # with a timeout of zero self.assertIsNotNone(ffp.wait()) # without a timeout ffp.close() self.assertEqual(ffp.reason, ffp.RC_EXITED) with self.assertRaisesRegex(AssertionError, ""): ffp._terminate() # pylint: disable=protected-access self.assertIsNone(ffp.wait(None))
def test_28(self): "test returncode" with open(self.tmpfn, "w") as prefs_fp: prefs_fp.write("//fftest_exit_code_3\n") tsrv = HTTPTestServer() self.addCleanup(tsrv.shutdown) ffp = FFPuppet() self.assertEqual(ffp.returncode, 0) self.addCleanup(ffp.clean_up) ffp.launch(TESTFF_BIN, prefs_js=self.tmpfn, location=self.tsrv.get_addr()) ffp.wait(10) self.assertFalse(ffp.is_running()) # verify private member is set when using returncode property self.assertIsNone(ffp._returncode) # pylint: disable=protected-access self.assertEqual(ffp.returncode, 3) self.assertEqual(ffp._returncode, 3) # pylint: disable=protected-access # verify private member is set when calling close() ffp._returncode = None # pylint: disable=protected-access ffp.close() self.assertEqual(ffp.reason, ffp.RC_EXITED) self.assertEqual(ffp.returncode, 3)
def test_28(self): "test launching with RR" if not sys.platform.startswith("linux"): with self.assertRaisesRegex(EnvironmentError, "RR is only supported on Linux"): FFPuppet(use_rr=True) else: try: # TODO: this can hang if ptrace is blocked by seccomp proc = subprocess.Popen(["rr", "check"], stdout=subprocess.PIPE, stderr=subprocess.PIPE) except OSError: self.skipTest("RR not installed") _, stderr = proc.communicate() proc.wait() if b"Unable to open performance counter" in stderr: self.skipTest( "This machine doesn't support performance counters needed by RR" ) ffp = FFPuppet(use_rr=True) self.addCleanup(ffp.clean_up) rr_dir = tempfile.mkdtemp(prefix="test_ffp_rr") self.addCleanup(shutil.rmtree, rr_dir, onerror=onerror) bin_path = str( subprocess.check_output(["which", "echo"]).strip().decode("ascii")) # launch will fail b/c 'echo' will exit right away but that's fine with self.assertRaisesRegex(LaunchError, "Failure during browser startup"): ffp.launch(bin_path, env_mod={"_RR_TRACE_DIR": rr_dir}) ffp.close() self.assertEqual(ffp.reason, ffp.RC_EXITED) ffp.save_logs(self.logs) with open(os.path.join(self.logs, "log_stderr.txt"), "rb") as log_fp: log_data = log_fp.read() # verify RR ran and executed the script self.assertIn(b"rr record", log_data) self.assertIn(b"[ffpuppet] Reason code:", log_data)
def test_15(self): "test passing a file and a non existing file to launch() via location" ffp = FFPuppet() self.addCleanup(ffp.clean_up) with self.assertRaisesRegex(IOError, "Cannot find"): ffp.launch(TESTFF_BIN, location="fake_file.none") ffp.close() with tempfile.NamedTemporaryFile() as test_fp: test_fp.write(b"test") test_fp.seek(0) # needs realpath() for OSX & normcase() for Windows fname = os.path.realpath(os.path.normcase(test_fp.name)) ffp.launch(TESTFF_BIN, location=fname) ffp.wait(0.25) # wait for log prints ffp.close() ffp.save_logs(self.logs) with open(os.path.join(self.logs, "log_stdout.txt"), "r") as log_fp: location = log_fp.read().strip() self.assertIn("url: file:///", location) location = os.path.normcase(location.split("file:///")[-1]) self.assertFalse(location.startswith("/")) self.assertEqual(os.path.normpath(os.path.join("/", location)), fname)
def test_13(self): "test calling close() and clean_up() in multiple states" ffp = FFPuppet() self.addCleanup(ffp.clean_up) ffp.close() ffp.launch(TESTFF_BIN, location=self.tsrv.get_addr()) self.assertIsNone(ffp.reason) ffp.close() ffp.clean_up() ffp.close()
class PuppetTarget(Target): def __init__(self, binary, extension, launch_timeout, log_limit, memory_limit, prefs, relaunch, **kwds): super(PuppetTarget, self).__init__(binary, extension, launch_timeout, log_limit, memory_limit, prefs, relaunch) self.use_rr = kwds.pop("rr", False) self.use_valgrind = kwds.pop("valgrind", False) use_xvfb = kwds.pop("xvfb", False) if kwds: log.warning("PuppetTarget ignoring unsupported arguments: %s", ", ".join(kwds)) # create Puppet object self._puppet = FFPuppet(use_rr=self.use_rr, use_valgrind=self.use_valgrind, use_xvfb=use_xvfb) def _abort_hung_proc(self): # send SIGABRT to the busiest process with self._lock: proc_usage = self._puppet.cpu_usage() for pid, cpu in sorted(proc_usage, reverse=True, key=lambda x: x[1]): log.debug("sending SIGABRT to pid: %r, cpu: %0.2f%%", pid, cpu) os.kill(pid, signal.SIGABRT) break def add_abort_token(self, token): self._puppet.add_abort_token(token) def cleanup(self): # prevent parallel calls to FFPuppet.clean_up() with self._lock: self._puppet.clean_up() def close(self): # prevent parallel calls to FFPuppet.close() with self._lock: self._puppet.close() @property def closed(self): return self._puppet.reason is not None @property def monitor(self): if self._monitor is None: class _PuppetMonitor(TargetMonitor): # pylint: disable=no-self-argument,protected-access def clone_log(_, log_id, offset=0): return self._puppet.clone_log(log_id, offset=offset) def is_running(_): return self._puppet.is_running() def is_healthy(_): return self._puppet.is_healthy() @property def launches(_): return self._puppet.launches def log_length(_, log_id): return self._puppet.log_length(log_id) self._monitor = _PuppetMonitor() return self._monitor def poll_for_idle(self, threshold, interval): # return POLL_IDLE if cpu usage of target is below threshold for interval seconds start_time = time.time() while time.time() - start_time < interval: for _, cpu in self._puppet.cpu_usage(): if cpu >= threshold: return self.POLL_BUSY if not self._puppet.is_running(): break else: log.info("Process utilized <= %d%% CPU for %ds", threshold, interval) return self.POLL_IDLE def detect_failure(self, ignored, was_timeout): status = self.RESULT_NONE if self.expect_close and not was_timeout: # give the browser a moment to close if needed self._puppet.wait(timeout=30) is_healthy = self._puppet.is_healthy() # check if there has been a crash, hang, etc... if not is_healthy or was_timeout: if self._puppet.is_running(): log.debug("terminating browser...") if was_timeout and "timeout" not in ignored: self._abort_hung_proc() # give the process a moment to start dump self._puppet.wait(timeout=1) self.close() # if something has happened figure out what if not is_healthy: if self._puppet.reason == FFPuppet.RC_CLOSED: log.info("target.close() was called") elif self._puppet.reason == FFPuppet.RC_EXITED: log.info("Target closed itself") elif (self._puppet.reason == FFPuppet.RC_WORKER and "memory" in ignored and "ffp_worker_memory_usage" in self._puppet.available_logs()): status = self.RESULT_IGNORED log.info("Memory limit exceeded") elif (self._puppet.reason == FFPuppet.RC_WORKER and "log-limit" in ignored and "ffp_worker_log_size" in self._puppet.available_logs()): status = self.RESULT_IGNORED log.info("Log size limit exceeded") else: log.debug("failure detected, ffpuppet return code: %r", self._puppet.reason) status = self.RESULT_FAILURE elif was_timeout: log.info("Timeout detected") status = self.RESULT_IGNORED if "timeout" in ignored else self.RESULT_FAILURE return status def dump_coverage(self): # If at this point, the browser is running, i.e. we did neither # relaunch nor crash/timeout, then we need to signal the browser # to dump coverage before attempting a new test that potentially # crashes. # Note: This is not required if we closed or are going to close # the browser (relaunch or done with all iterations) because the # SIGTERM will also trigger coverage to be synced out. pid = self._puppet.get_pid() if pid is None or not self._puppet.is_running(): log.debug("Could not dump coverage because process is not running") return try: for child in psutil.Process(pid).children(recursive=True): log.debug("Sending SIGUSR1 to %d", child.pid) os.kill(child.pid, signal.SIGUSR1) except (psutil.AccessDenied, psutil.NoSuchProcess): pass log.debug("Sending SIGUSR1 to %d", pid) os.kill(pid, signal.SIGUSR1) def launch(self, location, env_mod=None): if not self.prefs: raise TargetError("A prefs.js file is required") self.rl_countdown = self.rl_reset env_mod = dict(env_mod or []) # do not allow network connections to non local endpoints env_mod["MOZ_DISABLE_NONLOCAL_CONNECTIONS"] = "1" env_mod["MOZ_CRASHREPORTER_SHUTDOWN"] = "1" try: self._puppet.launch(self.binary, launch_timeout=self.launch_timeout, location=location, log_limit=self.log_limit, memory_limit=self.memory_limit, prefs_js=self.prefs, extension=self.extension, env_mod=env_mod) except LaunchError as exc: log.error("FFPuppet Error: %s", str(exc)) self.close() if isinstance(exc, BrowserTimeoutError): raise TargetLaunchTimeout(str(exc)) raise TargetLaunchError(str(exc)) def log_size(self): return self._puppet.log_length("stderr") + self._puppet.log_length( "stdout") def save_logs(self, *args, **kwargs): self._puppet.save_logs(*args, **kwargs)
class PuppetTarget(Target): SUPPORTED_ASSETS = ( # file containing line separated list of tokens to scan stderr/out for "abort-tokens", # xpi or directory containing the unpacked extension "extension", # LSan suppression list file "lsan-suppressions", # prefs.js file to use "prefs", # TSan suppression list file "tsan-suppressions", # UBSan suppression list file "ubsan-suppressions", ) TRACKED_ENVVARS = ( "ASAN_OPTIONS", "LSAN_OPTIONS", "TSAN_OPTIONS", "UBSAN_OPTIONS", "GNOME_ACCESSIBILITY", "MOZ_CHAOSMODE", "XPCOM_DEBUG_BREAK", ) __slots__ = ("use_valgrind", "_extension", "_prefs", "_puppet") def __init__(self, binary, launch_timeout, log_limit, memory_limit, **kwds): super().__init__( binary, launch_timeout, log_limit, memory_limit, assets=kwds.pop("assets", None), ) # TODO: clean up handling debuggers debugger = Debugger.NONE if kwds.pop("pernosco", False): debugger = Debugger.PERNOSCO if kwds.pop("rr", False): debugger = Debugger.RR if kwds.pop("valgrind", False): self.use_valgrind = True debugger = Debugger.VALGRIND self._extension = None self._prefs = None # create Puppet object self._puppet = FFPuppet( debugger=debugger, use_xvfb=kwds.pop("xvfb", False), working_path=grz_tmp("target"), ) if kwds: LOG.warning( "PuppetTarget ignoring unsupported arguments: %s", ", ".join(kwds) ) def _cleanup(self): # prevent parallel calls to FFPuppet.close() and/or FFPuppet.clean_up() with self._lock: self._puppet.clean_up() def close(self, force_close=False): # prevent parallel calls to FFPuppet.close() and/or FFPuppet.clean_up() with self._lock: self._puppet.close(force_close=force_close) @property def closed(self): return self._puppet.reason is not None def create_report(self, is_hang=False): logs = mkdtemp(prefix="logs_", dir=grz_tmp("logs")) self.save_logs(logs) return Report(logs, self.binary, is_hang=is_hang) def filtered_environ(self): # remove context specific entries from environment filtered = dict(self.environ) opts = SanitizerOptions() # iterate over *SAN_OPTIONS entries for san in (x for x in filtered if x.endswith("SAN_OPTIONS")): opts.load_options(filtered[san]) # remove entries specific to the current environment opts.pop("external_symbolizer_path") opts.pop("log_path") opts.pop("strip_path_prefix") opts.pop("suppressions") filtered[san] = opts.options # remove empty entries return {k: v for k, v in filtered.items() if v} def is_idle(self, threshold): for _, cpu in self._puppet.cpu_usage(): if cpu >= threshold: return False return True @property def monitor(self): if self._monitor is None: class _PuppetMonitor(TargetMonitor): # pylint: disable=no-self-argument,protected-access def clone_log(_, log_id, offset=0): return self._puppet.clone_log(log_id, offset=offset) def is_running(_): return self._puppet.is_running() def is_healthy(_): return self._puppet.is_healthy() @property def launches(_): return self._puppet.launches def log_length(_, log_id): return self._puppet.log_length(log_id) self._monitor = _PuppetMonitor() return self._monitor def check_result(self, ignored): result = Result.NONE # check if there has been a crash, hangs will appear as SIGABRT if not self._puppet.is_healthy(): self.close() # something has happened figure out what if self._puppet.reason == Reason.CLOSED: LOG.debug("target.close() was called") elif self._puppet.reason == Reason.EXITED: LOG.debug("target closed itself") elif ( self._puppet.reason == Reason.WORKER and "memory" in ignored and "ffp_worker_memory_usage" in self._puppet.available_logs() ): result = Result.IGNORED LOG.debug("memory limit exceeded") elif ( self._puppet.reason == Reason.WORKER and "log-limit" in ignored and "ffp_worker_log_size" in self._puppet.available_logs() ): result = Result.IGNORED LOG.debug("log size limit exceeded") else: # crash or hang (forced SIGABRT) has been detected LOG.debug("result detected (%s)", self._puppet.reason.name) result = Result.FOUND return result def handle_hang(self, ignore_idle=True): was_idle = False if self._puppet.is_healthy(): proc_usage = sorted(self._puppet.cpu_usage(), key=lambda x: x[1]) if proc_usage: pid, cpu = proc_usage.pop() if ignore_idle and cpu < 15: # don't send SIGABRT if process is idle LOG.debug("ignoring idle hang (%0.1f%%)", cpu) was_idle = True elif system() == "Linux": # sending SIGABRT is only supported on Linux for now # TODO: add/test on other OSs LOG.debug("sending SIGABRT to %r (%0.1f%%)", pid, cpu) try: kill(pid, SIGABRT) except OSError: LOG.warning("Failed to send SIGABRT to pid %d", pid) self._puppet.wait(timeout=10) # always call close() since this function should only/always # be called when there has been a timeout self.close() return was_idle def dump_coverage(self, timeout=15): assert SIGUSR1 is not None pid = self._puppet.get_pid() if pid is None or not self._puppet.is_healthy(): LOG.debug("Skipping coverage dump (target is not in a good state)") return # If at this point, the browser is in a good state, i.e. no crashes # or hangs, so signal the browser to dump coverage. try: for child in Process(pid).children(recursive=True): LOG.debug("Sending SIGUSR1 to %d (child)", child.pid) try: kill(child.pid, SIGUSR1) except OSError: LOG.warning("Failed to send SIGUSR1 to pid %d", child.pid) except (AccessDenied, NoSuchProcess): # pragma: no cover pass LOG.debug("Sending SIGUSR1 to %d (parent)", pid) try: kill(pid, SIGUSR1) except OSError: LOG.warning("Failed to send SIGUSR1 to pid %d", pid) start_time = time() gcda_found = False delay = 0.1 # wait for processes to write .gcno files # this should typically take less than 1 second while True: for proc in process_iter(attrs=["pid", "ppid", "open_files"]): # check if proc is the target or child process if pid in (proc.info["pid"], proc.info["ppid"]): if proc.info["open_files"] is None: continue if any(x.path.endswith(".gcda") for x in proc.info["open_files"]): gcda_found = True # get the pid of the process that has the file open gcda_open = proc.info["pid"] break else: gcda_open = None elapsed = time() - start_time if gcda_found: if gcda_open is None: # success LOG.debug("gcda dump took %0.2fs", elapsed) break if elapsed >= timeout: # timeout failure LOG.warning( "gcda file open by pid %d after %0.2fs", gcda_open, elapsed ) try: kill(gcda_open, SIGABRT) except OSError: pass sleep(1) self.close() break if delay < 1.0: # increase delay to a maximum of 1 second delay = min(1.0, delay + 0.1) elif elapsed >= 3: # assume we missed the process writing .gcno files LOG.warning("No gcda files seen after %0.2fs", elapsed) break if not self._puppet.is_healthy(): LOG.warning("Browser failure during dump_coverage()") break sleep(delay) def launch(self, location): # setup environment env_mod = dict(self.environ) # do not allow network connections to non local endpoints env_mod["MOZ_DISABLE_NONLOCAL_CONNECTIONS"] = "1" env_mod["MOZ_CRASHREPORTER_SHUTDOWN"] = "1" try: self._puppet.launch( self.binary, launch_timeout=self.launch_timeout, location=location, log_limit=self.log_limit, memory_limit=self.memory_limit, prefs_js=self._prefs, extension=self._extension, env_mod=env_mod, ) except LaunchError as exc: LOG.error("FFPuppet LaunchError: %s", str(exc)) self.close() if isinstance(exc, BrowserTimeoutError): raise TargetLaunchTimeout(str(exc)) from None raise TargetLaunchError(str(exc), self.create_report()) from None def log_size(self): return self._puppet.log_length("stderr") + self._puppet.log_length("stdout") def process_assets(self): self._extension = self.assets.get("extension") self._prefs = self.assets.get("prefs") # generate temporary prefs.js with prefpicker if self._prefs is None: LOG.debug("using prefpicker to generate prefs.js") with TemporaryDirectory(dir=grz_tmp("target")) as tmp_path: prefs = Path(tmp_path) / "prefs.js" template = PrefPicker.lookup_template("browser-fuzzing.yml") PrefPicker.load_template(template).create_prefsjs(prefs) self._prefs = self.assets.add("prefs", str(prefs), copy=False) abort_tokens = self.assets.get("abort-tokens") if abort_tokens: LOG.debug("loading 'abort tokens' from %r", abort_tokens) with open(abort_tokens, "r") as in_fp: for line in in_fp: line = line.strip() if line: self._puppet.add_abort_token(line) # configure sanitizer suppressions opts = SanitizerOptions() for sanitizer in ("lsan", "tsan", "ubsan"): asset = "%s-suppressions" % (sanitizer,) # load existing sanitizer options from environment var_name = "%s_OPTIONS" % (sanitizer.upper(),) opts.load_options(self.environ.get(var_name, "")) if self.assets.get(asset): # use suppression file if provided as asset opts.add("suppressions", repr(self.assets.get(asset)), overwrite=True) elif opts.get("suppressions"): supp_file = opts.pop("suppressions") if SanitizerOptions.is_quoted(supp_file): supp_file = supp_file[1:-1] if isfile(supp_file): # use environment specified suppression file LOG.debug("using %r from environment", asset) opts.add( "suppressions", repr(self.assets.add(asset, supp_file)), overwrite=True, ) else: LOG.warning("Missing %s suppressions file %r", sanitizer, supp_file) else: # nothing to do continue # update sanitized *SAN_OPTIONS LOG.debug("updating suppressions in %r", var_name) self.environ[var_name] = opts.options def save_logs(self, *args, **kwargs): self._puppet.save_logs(*args, **kwargs)
class PuppetTarget(Target): __slots__ = ("use_rr", "use_valgrind", "_puppet", "_remove_prefs") def __init__(self, binary, extension, launch_timeout, log_limit, memory_limit, **kwds): super().__init__(binary, extension, launch_timeout, log_limit, memory_limit) self.use_rr = kwds.pop("rr", False) self.use_valgrind = kwds.pop("valgrind", False) self._remove_prefs = False # create Puppet object self._puppet = FFPuppet(use_rr=self.use_rr, use_valgrind=self.use_valgrind, use_xvfb=kwds.pop("xvfb", False)) if kwds: LOG.warning("PuppetTarget ignoring unsupported arguments: %s", ", ".join(kwds)) def _abort_hung_proc(self): # send SIGABRT to the busiest process with self._lock: proc_usage = self._puppet.cpu_usage() for pid, cpu in sorted(proc_usage, reverse=True, key=lambda x: x[1]): LOG.debug("sending SIGABRT to pid: %r, cpu: %0.2f%%", pid, cpu) try: kill(pid, SIGABRT) except OSError: LOG.warning("Failed to send SIGABRT to pid %d", pid) break def add_abort_token(self, token): self._puppet.add_abort_token(token) def cleanup(self): # prevent parallel calls to FFPuppet.close() and/or FFPuppet.clean_up() with self._lock: self._puppet.clean_up() if self._remove_prefs and self._prefs and isfile(self._prefs): unlink(self._prefs) def close(self): # prevent parallel calls to FFPuppet.close() and/or FFPuppet.clean_up() with self._lock: self._puppet.close() @property def closed(self): return self._puppet.reason is not None def is_idle(self, threshold): for _, cpu in self._puppet.cpu_usage(): if cpu >= threshold: return False return True def create_report(self): logs = mkdtemp(prefix="logs_", dir=grz_tmp("logs")) self.save_logs(logs) return Report(logs, self.binary) @property def monitor(self): if self._monitor is None: class _PuppetMonitor(TargetMonitor): # pylint: disable=no-self-argument,protected-access def clone_log(_, log_id, offset=0): return self._puppet.clone_log(log_id, offset=offset) def is_running(_): return self._puppet.is_running() def is_healthy(_): return self._puppet.is_healthy() @property def launches(_): return self._puppet.launches def log_length(_, log_id): return self._puppet.log_length(log_id) self._monitor = _PuppetMonitor() return self._monitor def detect_failure(self, ignored, was_timeout): status = self.RESULT_NONE is_healthy = self._puppet.is_healthy() # check if there has been a crash, hang, etc... if not is_healthy or was_timeout: if self._puppet.is_running(): LOG.debug("terminating browser...") if was_timeout and "timeout" not in ignored and system( ) == "Linux": self._abort_hung_proc() # give the process a moment to start dump self._puppet.wait(timeout=1) self.close() # if something has happened figure out what if not is_healthy: if self._puppet.reason == FFPuppet.RC_CLOSED: LOG.debug("target.close() was called") elif self._puppet.reason == FFPuppet.RC_EXITED: LOG.debug("target closed itself") elif (self._puppet.reason == FFPuppet.RC_WORKER and "memory" in ignored and "ffp_worker_memory_usage" in self._puppet.available_logs()): status = self.RESULT_IGNORED LOG.debug("memory limit exceeded") elif (self._puppet.reason == FFPuppet.RC_WORKER and "log-limit" in ignored and "ffp_worker_log_size" in self._puppet.available_logs()): status = self.RESULT_IGNORED LOG.debug("log size limit exceeded") else: LOG.debug("failure detected, ffpuppet reason %r", self._puppet.reason) status = self.RESULT_FAILURE elif was_timeout: LOG.debug("timeout detected") status = self.RESULT_IGNORED if "timeout" in ignored else self.RESULT_FAILURE return status def dump_coverage(self, timeout=15): assert SIGUSR1 is not None pid = self._puppet.get_pid() if pid is None or not self._puppet.is_healthy(): LOG.debug("Skipping coverage dump (target is not in a good state)") return # If at this point, the browser is in a good state, i.e. no crashes # or hangs, so signal the browser to dump coverage. try: for child in Process(pid).children(recursive=True): LOG.debug("Sending SIGUSR1 to %d (child)", child.pid) try: kill(child.pid, SIGUSR1) except OSError: LOG.warning("Failed to send SIGUSR1 to pid %d", child.pid) except (AccessDenied, NoSuchProcess): # pragma: no cover pass LOG.debug("Sending SIGUSR1 to %d (parent)", pid) try: kill(pid, SIGUSR1) except OSError: LOG.warning("Failed to send SIGUSR1 to pid %d", pid) start_time = time() gcda_found = False delay = 0.1 # wait for processes to write .gcno files # this should typically take less than 1 second while True: for proc in process_iter(attrs=["pid", "ppid", "open_files"]): # check if proc is the target or child process if pid in (proc.info["pid"], proc.info["ppid"]): if proc.info["open_files"] is None: continue if any( x.path.endswith(".gcda") for x in proc.info["open_files"]): gcda_found = True # get the pid of the process that has the file open gcda_open = proc.info["pid"] break else: gcda_open = None elapsed = time() - start_time if gcda_found: if gcda_open is None: # success LOG.debug("gcda dump took %0.2fs", elapsed) break if elapsed >= timeout: # timeout failure LOG.warning("gcda file open by pid %d after %0.2fs", gcda_open, elapsed) try: kill(gcda_open, SIGABRT) except OSError: pass sleep(1) self.close() break if delay < 1.0: # increase delay to a maximum of 1 second delay = min(1.0, delay + 0.1) elif elapsed >= 3: # assume we missed the process writing .gcno files LOG.warning("No gcda files seen after %0.2fs", elapsed) break if not self._puppet.is_healthy(): LOG.warning("Browser failure during dump_coverage()") break sleep(delay) def launch(self, location, env_mod=None): # setup environment env_mod = dict(env_mod or []) # do not allow network connections to non local endpoints env_mod["MOZ_DISABLE_NONLOCAL_CONNECTIONS"] = "1" env_mod["MOZ_CRASHREPORTER_SHUTDOWN"] = "1" try: self._puppet.launch(self.binary, launch_timeout=self.launch_timeout, location=location, log_limit=self.log_limit, memory_limit=self.memory_limit, prefs_js=self.prefs, extension=self.extension, env_mod=env_mod) except LaunchError as exc: LOG.error("FFPuppet LaunchError: %s", str(exc)) self.close() if isinstance(exc, BrowserTimeoutError): raise TargetLaunchTimeout(str(exc)) from None raise TargetLaunchError(str(exc), self.create_report()) from None def log_size(self): return self._puppet.log_length("stderr") + self._puppet.log_length( "stdout") @property def prefs(self): if self._prefs is None: # generate temporary prefs.js for prefs_template in PrefPicker.templates(): if prefs_template.endswith("browser-fuzzing.yml"): LOG.debug("using prefpicker template %r", prefs_template) tmp_fd, self._prefs = mkstemp(prefix="prefs_", suffix=".js", dir=grz_tmp()) close(tmp_fd) PrefPicker.load_template(prefs_template).create_prefsjs( self._prefs) LOG.debug("generated prefs.js %r", self._prefs) self._remove_prefs = True break else: # pragma: no cover raise TargetError("Failed to generate prefs.js") return self._prefs @prefs.setter def prefs(self, prefs_file): if self._remove_prefs and self._prefs and isfile(self._prefs): unlink(self._prefs) if prefs_file is None: self._prefs = None self._remove_prefs = True elif isfile(prefs_file): self._prefs = abspath(prefs_file) self._remove_prefs = False else: raise TargetError("Missing prefs.js file %r" % (prefs_file, )) def save_logs(self, *args, **kwargs): self._puppet.save_logs(*args, **kwargs)