From bb97c818320fee600d7a75298cd28d98eee9cb81 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Sat, 2 Feb 2019 19:09:26 -0800 Subject: [PATCH 01/16] make: Rework clean target in database/Makefile * Have targets for only removing the database and not the harness / gridinfo tool. * Have seperate targets for cleaning each database. Signed-off-by: Tim 'mithro' Ansell --- database/Makefile | 33 +++++++++++++++++++++++++++++++-- 1 file changed, 31 insertions(+), 2 deletions(-) diff --git a/database/Makefile b/database/Makefile index d8060369..082ade76 100644 --- a/database/Makefile +++ b/database/Makefile @@ -1,3 +1,32 @@ -clean: - rm -f $$(ls */* |grep -v settings.sh) +DATABASE_FILES = *.csv *.db *.json *.yaml + +clean-artix7-db: + rm -f $(addprefix artix7/,$(DATABASE_FILES)) + +clean-kintex7-db: + rm -f $(addprefix kintex7/,$(DATABASE_FILES)) + +clean-zynq7-db: + rm -f $(addprefix zynq7/,$(DATABASE_FILES)) + +clean-db: clean-artix7-db clean-kintex7-db clean-zynq7-db + @true + +clean: clean-db + @true + +.PHONY: clean-artix7-db clean-kintex7-db clean-zynq7-db clean-db clean + +reset: + git reset --hard + +.PHONY: reset + +update: + git stash + git fetch origin + git merge origin/master + git stash pop + +.PHONY: update From 7985d0c58c926fdb503edcc95fdc71f1b9c8ba56 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Sun, 3 Feb 2019 06:05:01 -0800 Subject: [PATCH 02/16] make: Pass the jobserver info down. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/fuzzer.mk | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/fuzzers/fuzzer.mk b/fuzzers/fuzzer.mk index 16497416..0f260ea2 100644 --- a/fuzzers/fuzzer.mk +++ b/fuzzers/fuzzer.mk @@ -6,9 +6,16 @@ FUZDIR ?= ${PWD} all: database +# generate.sh / top_generate.sh call make, hence the command must +# have a + before it. $(SPECIMENS_OK): mkdir -p build - if [ -f $(FUZDIR)/generate.sh ]; then export $(ENV_VAR); bash $(FUZDIR)/generate.sh $(subst /OK,,$@); else bash ${XRAY_DIR}/utils/top_generate.sh $(subst /OK,,$@); fi + +if [ -f $(FUZDIR)/generate.sh ]; then \ + export $(ENV_VAR); \ + bash $(FUZDIR)/generate.sh $(subst /OK,,$@); \ + else \ + bash ${XRAY_DIR}/utils/top_generate.sh $(subst /OK,,$@); \ + fi run: $(MAKE) clean From 378e5f40b144ea8f82090fc2e35d47259f1c3364 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 16:30:20 -0800 Subject: [PATCH 03/16] make: Add `+` so make passes down job information. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/pip_loop.mk | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/fuzzers/pip_loop.mk b/fuzzers/pip_loop.mk index e2a14a26..1c1497b9 100644 --- a/fuzzers/pip_loop.mk +++ b/fuzzers/pip_loop.mk @@ -55,10 +55,10 @@ build/database/seeded: cp ${XRAY_DATABASE_DIR}/${XRAY_DATABASE}/segbits*.db build/database/${XRAY_DATABASE} touch build/database/seeded -# XXX: conider moving to script +# FIXME: consider moving to script run: $(MAKE) clean - XRAY_DIR=${XRAY_DIR} MAKE="$(MAKE)" QUICK=$(QUICK) $(XRAY_DIR)/fuzzers/int_loop.sh --check-args "$(CHECK_ARGS)" + +$(XRAY_DIR)/fuzzers/int_loop.sh --check-args "$(CHECK_ARGS)" touch run.ok clean: @@ -72,4 +72,3 @@ cleanpiplist: rm -rf $(XRAY_FUZZERS_DIR)/piplist/build .PHONY: all database pushdb run clean cleaniter cleanpiplist - From f8c3ada04172f5324c0e10646371e9df6e924606 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Fri, 1 Feb 2019 00:27:56 -0800 Subject: [PATCH 04/16] Adding wrapper to get understandable output. * Saves stdout / stderr to log files. * Prefixes all messages with fuzzer name. * Gives regular status updates. * Successfully passes jobserver details down. * Correctly handles dry-run and question options. Signed-off-by: Tim 'mithro' Ansell --- .gitignore | 2 + fuzzers/Makefile | 17 +- fuzzers/run_fuzzer.py | 528 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 546 insertions(+), 1 deletion(-) create mode 100755 fuzzers/run_fuzzer.py diff --git a/.gitignore b/.gitignore index f9585e4e..17ed9a27 100644 --- a/.gitignore +++ b/.gitignore @@ -5,5 +5,7 @@ **/specimen_* **/output run.ok +stderr.*.log +stdout.*.log __pycache__ *.pyc diff --git a/fuzzers/Makefile b/fuzzers/Makefile index be8c70d8..e3dbe9fb 100644 --- a/fuzzers/Makefile +++ b/fuzzers/Makefile @@ -1,3 +1,5 @@ +SELF_DIR := $(dir $(lastword $(MAKEFILE_LIST))) + # Developer options for quicker runs # Run algorithm, but only a small number of iterations QUICK=N @@ -11,11 +13,24 @@ BITONLY=N all: define fuzzer + +# $(1) - Fuzzer name/directory +# $(2) - Space seperated list of dependencies for the fuzzer. + +# Make the all target depend on the run.ok file for the fuzzer. all: $(1)/run.ok + +# Make the clean target run `make clean` in the fuzzer's directory. clean:: $$(MAKE) -C $(1) clean + rm -f $(1)/*.log + +# Describe how to create the fuzzer's run.ok file. +# This command must start with a + to tell make to pass the jobserver +# parameters downwards. $(1)/run.ok: $(addsuffix /run.ok,$(2)) - $$(MAKE) -C $(1) run + +@$(SELF_DIR)/run_fuzzer.py $(1) + endef $(eval $(call fuzzer,000-init-db,)) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py new file mode 100755 index 00000000..3e4eeda6 --- /dev/null +++ b/fuzzers/run_fuzzer.py @@ -0,0 +1,528 @@ +#!/usr/bin/env python3 + +from datetime import datetime, timedelta + +import io +import os +import os.path +import re +import resource +import signal +import subprocess +import sys +import traceback + +secs_in_min = 60 +secs_in_hour = 60 * secs_in_min + + +def pretty_timedelta_str(d): + """Pretty print a time delta object. + + >>> pretty_timedelta_str(timedelta(seconds=2)) + '2s' + + >>> pretty_timedelta_str(timedelta(seconds=61)) + '1m01s' + + >>> pretty_timedelta_str(timedelta(seconds=125)) + '2m05s' + + >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5)) + '5h' + + Once we get to displaying hours, we don't bother displaying seconds. + >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5 + 1)) + '5h' + + >>> pretty_timedelta_str(timedelta( + ... seconds=secs_in_hour * 5 + secs_in_min * 2 + 1)) + '5h02m' + + >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5.5)) + '5h30m' + """ + assert isinstance(d, timedelta) + ts = d.total_seconds() + assert ts > 0, (d, ts) + + bits = [] + hours = int(ts / secs_in_hour) + if hours > 0: + bits.append("{}h".format(hours)) + ts -= hours * secs_in_hour + + mins = int(ts / secs_in_min) + if mins > 0: + if hours > 0: + bits.append("{:02d}m".format(mins)) + else: + bits.append("{:d}m".format(mins)) + ts -= mins * secs_in_min + + if hours == 0: + if mins > 0: + bits.append("{:02d}s".format(int(ts))) + else: + bits.append("{:d}s".format(int(ts))) + + assert len(bits) > 0, d + + return "".join(bits) + + +class Logger: + """Output a bunch of lines with a prefix. + + >>> l = Logger("fuzz", datetime(2001, 11, 1), 6) + >>> l._now = lambda: datetime(2001, 11, 1, second=10) + >>> l.log("Test!") + fuzz - 10s: Test! + >>> l.log("Format {} {t}", [1,], {'t': 2}) + fuzz - 10s: Format 1 2 + >>> l.log('''\\ + ... Line 1 + ... Line 2 + ... Line 3 + ... ''') + fuzz - 10s: Line 1 + fuzz - 10s: Line 2 + fuzz - 10s: Line 3 + """ + + def __init__(self, fuzzer, time_start, padding): + self.fuzzer = fuzzer + ' ' * (padding - len(fuzzer)) + self.time_start = time_start + self.queue = [] + + def _now(self): + return datetime.utcnow() + + def log(self, msg, args=None, kw=None, flush=True): + """Queue a log message. + + This is safe to do in a signal handler where you can't do io. + """ + if args is None: + args = [] + if kw is None: + kw = {} + + time_log = self._now() + self.queue.append((time_log, msg, args, kw)) + if flush: + self.flush() + + def flush(self): + while len(self.queue) > 0: + time_log, msg, args, kw = self.queue.pop(0) + self._output(time_log, msg, args, kw) + + def _output(self, time_log, msg, args, kw): + running_for = time_log - self.time_start + msg = msg.format(*args, **kw) + + log_prefix = "{:s} - {:>5s}: ".format( + self.fuzzer, pretty_timedelta_str(running_for)) + + msg = "\n".join(log_prefix + x for x in msg.splitlines()) + print(msg) + + +def last_lines(f, num, blocksize=100): + r"""Return n last lines in a file. + + >>> f = io.StringIO("") + >>> last_lines(f, 100) + [''] + + >>> f = io.StringIO("1\n2") + >>> last_lines(f, 100) + ['1', '2'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 100) + ['11', '22', '33', '44', '55'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 100, 2) + ['11', '22', '33', '44', '55'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 100, 3) + ['11', '22', '33', '44', '55'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 2, 2) + ['44', '55'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 2, 3) + ['44', '55'] + + >>> f = io.StringIO("11\n22\n33\n44\n55") + >>> last_lines(f, 2, 4) + ['44', '55'] + + >>> f = io.StringIO("1\n22\n3333333\n") + >>> last_lines(f, 100, 3) + ['1', '22', '3333333', ''] + + """ + lines = [''] + # Seek to the end of the file + f.seek(0, os.SEEK_END) + fpos = f.tell() + + while len(lines) < (num + 1) and fpos > 0: + bs = min(blocksize, fpos) + fpos = fpos - bs + f.seek(fpos) + data = f.read(bs) + + while True: + lpos = data.rfind('\n') + lines[0] = data[lpos + 1:] + lines[0] + if lpos == -1: + break + lines.insert(0, '') + data = data[:lpos] + + if fpos == 0: + lines.insert(0, '') + + return lines[1:] + + +def get_usage(): + # This function only works if you have a signal handler for the + # signal.SIGCHLD signal. + raw_usage = resource.getrusage(resource.RUSAGE_CHILDREN) + # 0 ru_utime time in user mode (float) + # 1 ru_stime time in system mode (float) + # 2 ru_maxrss maximum resident set size + # + # These fields are always zero on Linux + # 3 ru_ixrss shared memory size + # 4 ru_idrss unshared memory size + # 5 ru_isrss unshared stack size + return "User:{}s System:{}s".format( + int(raw_usage.ru_utime), + int(raw_usage.ru_stime), + ) + + +def get_load(): + """Return current load average. + + Values is average perecntage of CPU used over 1 minute, 5 minutes, 15 + minutes. + """ + a1, a5, a15 = os.getloadavg() + cpus = os.cpu_count() + return a1 / cpus * 100.0, a5 / cpus * 100.0, a15 / cpus * 100.0 + + +_pstree_features = None + + +def get_pstree_features(): + global _pstree_features + if _pstree_features is None: + _pstree_features = [] + for f in ['-T', '-l']: + try: + subprocess.check_output( + "pstree {}".format(f), + stderr=subprocess.STDOUT, + shell=True, + ) + _pstree_features.append(f) + except subprocess.CalledProcessError: + continue + return _pstree_features + + +def get_pstree(pid): + """Get processes under current one. + + Requires the pstree until be installed, otherwise returns empty string. + """ + p = subprocess.Popen( + "pstree {} {}".format(" ".join(get_pstree_features()), pid), + shell=True, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + stdin=subprocess.DEVNULL, + universal_newlines=True, + ) + stdout, stderr = p.communicate() + + # Special case segfaults. + if 'Segmentation fault' in stderr: + stderr = '' + stdout = '(result to big, pstree segfaulted.)' + + # If no error, just return stdout + if not stderr: + return stdout + + return "{}\n{}".format(stdout, stderr) + + +def run_submake(make_flags): + """Check if make_flags indicate that we should execute things. + + See https://www.gnu.org/software/make/manual/html_node/Instead-of-Execution.html#Instead-of-Execution # noqa + + If this is a dry run or question then we shouldn't execute or output + anything. + + The flags end up as single letter versions in the MAKEFLAGS environment + variable. + + >>> run_submake('') + True + + The following flags are important; + + -n == --dry-run + + >>> run_submake('n') + False + >>> run_submake('n --blah') + False + >>> run_submake('--blah n') + False + >>> run_submake('--blah') + True + >>> run_submake('--random') + True + + -q == --question + + >>> run_submake('q') + False + >>> run_submake('q --blah') + False + >>> run_submake('--blah q') + False + >>> run_submake('--blah') + True + >>> run_submake('--random') + True + + Both --dry-run and --question + + >>> run_submake('qn') + False + >>> run_submake('nq') + False + >>> run_submake('--quiant') + True + """ + r = re.search(r'(?:^|\s)[^-]*(n|q)[^\s]*(\s|$)', make_flags) + if not r: + return True + return not bool(r.groups()[0]) + + +def main(argv): + fuzzers = os.path.abspath(os.path.dirname(__file__)) + + assert len(argv) == 2, argv + fuzzer = argv[1] + + make_cmd = os.environ.get('MAKE', 'make') + make_flags = os.environ.get('MAKEFLAGS', '') + + # Should run things? + if not run_submake(make_flags): + return 0 + + time_start = datetime.utcnow() + + fuzzer_length = max(len(f) for f in os.listdir(fuzzers)) + + logger = Logger(fuzzer, time_start, fuzzer_length) + + def log(msg, *a, **k): + logger.log(msg, a, k, flush=True) + + # Need a signal handler on SIGCHLD otherwise get_resource doesn't return + # anything. + signal.signal(signal.SIGCHLD, lambda sig, frame: None) + + fuzzer_dir = os.path.join(fuzzers, fuzzer) + assert os.path.exists(fuzzer_dir), fuzzer_dir + # FIXME: The fuzzer output directory should be different from the top level + # fuzzer directory. + fuzzer_out = fuzzer_dir + if not os.path.exists(fuzzer_out): + os.makedirs(fuzzer_out) + assert os.path.exists(fuzzer_out) + + fuzzer_runok = os.path.join(fuzzer_out, "run.ok") + + if os.path.exists(fuzzer_runok): + last_modified = datetime.fromtimestamp(os.stat(fuzzer_runok).st_mtime) + + log( + "Skipping as run.ok exists (updated @ {})", + last_modified.isoformat()) + else: + log("Starting @ {}", time_start.isoformat()) + + log_suffix = ".{}.log".format(time_start.isoformat()) + fuzzer_stdout = os.path.join(fuzzer_out, "stdout" + log_suffix) + fuzzer_stderr = os.path.join(fuzzer_out, "stderr" + log_suffix) + + # Make sure the stdout file exists + stdout_fd = open(fuzzer_stdout, "w") + stdout_fd.write("Build started {}\n".format(time_start.isoformat())) + stdout_fd.write("-" * 75) + stdout_fd.write("\n") + stdout_fd.flush() + os.fsync(stdout_fd) + stdout_fd.close() + + stdout_fd = open(fuzzer_stdout, "w+") + stdout_fd.seek(0, os.SEEK_END) + + # Make sure the stderr file exists + stderr_fd = open(fuzzer_stderr, "w") + stderr_fd.write("Build started {}\n".format(time_start.isoformat())) + stderr_fd.write("-" * 75) + stderr_fd.write("\n") + stderr_fd.flush() + os.fsync(stderr_fd) + stderr_fd.close() + + stderr_fd = open(fuzzer_stderr, "w+") + stderr_fd.seek(0, os.SEEK_END) + + # Play nice with make's jobserver. + # See https://www.gnu.org/software/make/manual/html_node/POSIX-Jobserver.html#POSIX-Jobserver # noqa + if '--jobserver-fds' in make_flags: + job_re = re.search('--jobserver-fds=([0-9]+),([0-9]+)', make_flags) + assert job_re, make_flags + job_rd, job_wr = job_re.groups() + + job_rd = int(job_rd) + job_wr = int(job_wr) + assert job_rd > 2, (job_rd, job_wr, make_flags) + assert job_wr > 2, (job_rd, job_wr, make_flags) + + # Make sure the file descriptors exist.. + job_rd_fd = os.fdopen(int(job_rd), 'rb', 0) + job_wr_fd = os.fdopen(int(job_wr), 'rb', 0) + else: + job_rd_fd = None + job_wr_fd = None + + p = None + try: + log( + "Running {} -C {} run (with MAKEFLAGS='{}')", + make_cmd, + fuzzer_dir, + make_flags, + ) + p = subprocess.Popen( + [make_cmd, '-C', fuzzer_dir, 'run'], + stdin=None, + stdout=stdout_fd, + stderr=stderr_fd, + # Make sure not to close the fds as make uses fd=(3,4) for process + # control. + close_fds=False) + + # Close the jobserver files if they were found. + if job_rd_fd: + job_rd_fd.close() + if job_wr_fd: + job_wr_fd.close() + + while True: + try: + retcode = p.wait(timeout=10) + p = None + except subprocess.TimeoutExpired: + retcode = None + + if retcode is not None: + break + log( + "Still running (1m:{:0.2f}%, 5m:{:0.2f}%, 15m:{:0.2f}%).\n{}", + *get_load(), + get_pstree(p.pid), + ) + except (Exception, KeyboardInterrupt, SystemExit): + retcode = -1 + tb = io.StringIO() + traceback.print_exc(file=tb) + log(tb.getvalue()) + + # Prevent Ctrl-C so we exit properly... + signal.signal(signal.SIGINT, lambda sig, frame: logger.log("Dieing!")) + + try: + if p is not None: + try: + retcode = p.wait(1) + except subprocess.TimeoutExpired: + retcode = -1 + p.kill() + p.wait() + except Exception: + tb = io.StringIO() + traceback.print_exc(file=tb) + log(tb.getvalue()) + + # Wait for all children to finish. + try: + while True: + log("Child finished: {}", os.waitpid(-1, 0)) + except ChildProcessError: + pass + + log("Finishing ({}).", get_usage()) + + time_end = datetime.utcnow() + if retcode != 0: + # Log the last 100 lines of stderr on a failure + error_log = "\n".join(last_lines(open(fuzzer_stderr), 100)) + log( + """\ +Failed @ {time_end} with exit code: {retcode} +-------------------------------------------------------------------------- +{error_log} +-------------------------------------------------------------------------- +Failed @ {time_end} with exit code: {retcode} +""", + retcode=retcode, + error_log=error_log, + time_end=time_end.isoformat()) + + else: + + # Log the last 100 lines of a successful run + success_log = "\n".join(last_lines(open(fuzzer_stdout), 100)) + log( + """\ +Succeeded! @ {} +-------------------------------------------------------------------------- +{} +-------------------------------------------------------------------------- +""", time_end.isoformat(), success_log) + + logger.flush() + return retcode + + +if __name__ == "__main__": + if "--test" in sys.argv or len(sys.argv) == 1: + import doctest + doctest.testmod() + else: + sys.exit(main(sys.argv)) From 6249f24fd21ab0a2c34bb8f31b96319ea37a9d94 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 17:25:04 +1100 Subject: [PATCH 05/16] fuzzers: Use make directly when VERBOSE=Y Signed-off-by: Tim 'mithro' Ansell --- .gitignore | 3 +-- fuzzers/Makefile | 14 +++++++++++++- 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/.gitignore b/.gitignore index 17ed9a27..95264834 100644 --- a/.gitignore +++ b/.gitignore @@ -1,11 +1,10 @@ /env/ /build/ +/logs/ /database/ .Xil **/specimen_* **/output run.ok -stderr.*.log -stdout.*.log __pycache__ *.pyc diff --git a/fuzzers/Makefile b/fuzzers/Makefile index e3dbe9fb..fad56d03 100644 --- a/fuzzers/Makefile +++ b/fuzzers/Makefile @@ -23,14 +23,26 @@ all: $(1)/run.ok # Make the clean target run `make clean` in the fuzzer's directory. clean:: $$(MAKE) -C $(1) clean - rm -f $(1)/*.log + rm -rf $(1)/logs # Describe how to create the fuzzer's run.ok file. # This command must start with a + to tell make to pass the jobserver # parameters downwards. +ifeq ($(VERBOSE),Y) + +# When verbose we just call make directory +$(1)/run.ok: $(addsuffix /run.ok,$(2)) + $(MAKE) $(1) + +else + +# When not verbose, we use the run_fuzzer wrapper which will save the results +# to log files. $(1)/run.ok: $(addsuffix /run.ok,$(2)) +@$(SELF_DIR)/run_fuzzer.py $(1) +endif + endef $(eval $(call fuzzer,000-init-db,)) From 314ee62b3f9a91fd258e1f0ee229bfd3c6ea8ccb Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 16:24:16 -0800 Subject: [PATCH 06/16] Fixing number of review comments. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/Makefile | 2 +- fuzzers/run_fuzzer.py | 126 ++++++++++++++++++++---------------------- 2 files changed, 62 insertions(+), 66 deletions(-) diff --git a/fuzzers/Makefile b/fuzzers/Makefile index fad56d03..20754216 100644 --- a/fuzzers/Makefile +++ b/fuzzers/Makefile @@ -32,7 +32,7 @@ ifeq ($(VERBOSE),Y) # When verbose we just call make directory $(1)/run.ok: $(addsuffix /run.ok,$(2)) - $(MAKE) $(1) + $$(MAKE) -C $(1) run else diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 3e4eeda6..f21c4648 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -2,6 +2,8 @@ from datetime import datetime, timedelta +import argparse +import collections import io import os import os.path @@ -93,7 +95,7 @@ class Logger: def __init__(self, fuzzer, time_start, padding): self.fuzzer = fuzzer + ' ' * (padding - len(fuzzer)) self.time_start = time_start - self.queue = [] + self.queue = collections.deque() def _now(self): return datetime.utcnow() @@ -115,7 +117,7 @@ class Logger: def flush(self): while len(self.queue) > 0: - time_log, msg, args, kw = self.queue.pop(0) + time_log, msg, args, kw = self.queue.popleft() self._output(time_log, msg, args, kw) def _output(self, time_log, msg, args, kw): @@ -126,7 +128,7 @@ class Logger: self.fuzzer, pretty_timedelta_str(running_for)) msg = "\n".join(log_prefix + x for x in msg.splitlines()) - print(msg) + print(msg, flush=True) def last_lines(f, num, blocksize=100): @@ -169,7 +171,7 @@ def last_lines(f, num, blocksize=100): ['1', '22', '3333333', ''] """ - lines = [''] + lines = collections.deque(['']) # Seek to the end of the file f.seek(0, os.SEEK_END) fpos = f.tell() @@ -191,7 +193,7 @@ def last_lines(f, num, blocksize=100): if fpos == 0: lines.insert(0, '') - return lines[1:] + return list(lines)[1:] def get_usage(): @@ -261,7 +263,7 @@ def get_pstree(pid): # Special case segfaults. if 'Segmentation fault' in stderr: stderr = '' - stdout = '(result to big, pstree segfaulted.)' + stdout = '(result too big, pstree segfaulted.)' # If no error, just return stdout if not stderr: @@ -270,7 +272,7 @@ def get_pstree(pid): return "{}\n{}".format(stdout, stderr) -def run_submake(make_flags): +def should_run_submake(make_flags): """Check if make_flags indicate that we should execute things. See https://www.gnu.org/software/make/manual/html_node/Instead-of-Execution.html#Instead-of-Execution # noqa @@ -281,44 +283,44 @@ def run_submake(make_flags): The flags end up as single letter versions in the MAKEFLAGS environment variable. - >>> run_submake('') + >>> should_run_submake('') True The following flags are important; -n == --dry-run - >>> run_submake('n') + >>> should_run_submake('n') False - >>> run_submake('n --blah') + >>> should_run_submake('n --blah') False - >>> run_submake('--blah n') + >>> should_run_submake('--blah n') False - >>> run_submake('--blah') + >>> should_run_submake('--blah') True - >>> run_submake('--random') + >>> should_run_submake('--random') True -q == --question - >>> run_submake('q') + >>> should_run_submake('q') False - >>> run_submake('q --blah') + >>> should_run_submake('q --blah') False - >>> run_submake('--blah q') + >>> should_run_submake('--blah q') False - >>> run_submake('--blah') + >>> should_run_submake('--blah') True - >>> run_submake('--random') + >>> should_run_submake('--random') True Both --dry-run and --question - >>> run_submake('qn') + >>> should_run_submake('qn') False - >>> run_submake('nq') + >>> should_run_submake('nq') False - >>> run_submake('--quiant') + >>> should_run_submake('--quiant') True """ r = re.search(r'(?:^|\s)[^-]*(n|q)[^\s]*(\s|$)', make_flags) @@ -330,21 +332,23 @@ def run_submake(make_flags): def main(argv): fuzzers = os.path.abspath(os.path.dirname(__file__)) - assert len(argv) == 2, argv - fuzzer = argv[1] + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("fuzzer", help="fuzzer to run") + args = parser.parse_args() make_cmd = os.environ.get('MAKE', 'make') make_flags = os.environ.get('MAKEFLAGS', '') # Should run things? - if not run_submake(make_flags): + if not should_run_submake(make_flags): return 0 time_start = datetime.utcnow() + # Setup the logger with flush=False, it should be safe to use in a signal + # handler. fuzzer_length = max(len(f) for f in os.listdir(fuzzers)) - - logger = Logger(fuzzer, time_start, fuzzer_length) + logger = Logger(args.fuzzer, time_start, fuzzer_length) def log(msg, *a, **k): logger.log(msg, a, k, flush=True) @@ -353,17 +357,16 @@ def main(argv): # anything. signal.signal(signal.SIGCHLD, lambda sig, frame: None) - fuzzer_dir = os.path.join(fuzzers, fuzzer) + fuzzer_dir = os.path.join(fuzzers, args.fuzzer) assert os.path.exists(fuzzer_dir), fuzzer_dir # FIXME: The fuzzer output directory should be different from the top level # fuzzer directory. - fuzzer_out = fuzzer_dir - if not os.path.exists(fuzzer_out): - os.makedirs(fuzzer_out) - assert os.path.exists(fuzzer_out) - - fuzzer_runok = os.path.join(fuzzer_out, "run.ok") + fuzzer_logdir = os.path.join(fuzzer_dir, "logs") + if not os.path.exists(fuzzer_logdir): + os.makedirs(fuzzer_logdir) + assert os.path.exists(fuzzer_logdir) + fuzzer_runok = os.path.join(fuzzer_logdir, "run.ok") if os.path.exists(fuzzer_runok): last_modified = datetime.fromtimestamp(os.stat(fuzzer_runok).st_mtime) @@ -373,33 +376,31 @@ def main(argv): else: log("Starting @ {}", time_start.isoformat()) + running_msg = "Running {} -C {} run (with MAKEFLAGS='{}')".format( + make_cmd, + fuzzer_dir, + make_flags, + ) + log(running_msg) + log_suffix = ".{}.log".format(time_start.isoformat()) - fuzzer_stdout = os.path.join(fuzzer_out, "stdout" + log_suffix) - fuzzer_stderr = os.path.join(fuzzer_out, "stderr" + log_suffix) + fuzzer_stdout = os.path.join(fuzzer_logdir, "stdout" + log_suffix) + fuzzer_stderr = os.path.join(fuzzer_logdir, "stderr" + log_suffix) - # Make sure the stdout file exists - stdout_fd = open(fuzzer_stdout, "w") - stdout_fd.write("Build started {}\n".format(time_start.isoformat())) - stdout_fd.write("-" * 75) - stdout_fd.write("\n") - stdout_fd.flush() - os.fsync(stdout_fd) - stdout_fd.close() + # Write header to stdout/stderr to make sure they match. + for fname in [fuzzer_stdout, fuzzer_stderr]: + with open(fname, "w") as fd: + fd.write("Build starting @ {}\n".format(time_start.isoformat())) + fd.write(running_msg) + fd.write("\n") + fd.write("-" * 75) + fd.write("\n") + fd.flush() + os.fsync(fd) - stdout_fd = open(fuzzer_stdout, "w+") - stdout_fd.seek(0, os.SEEK_END) - - # Make sure the stderr file exists - stderr_fd = open(fuzzer_stderr, "w") - stderr_fd.write("Build started {}\n".format(time_start.isoformat())) - stderr_fd.write("-" * 75) - stderr_fd.write("\n") - stderr_fd.flush() - os.fsync(stderr_fd) - stderr_fd.close() - - stderr_fd = open(fuzzer_stderr, "w+") - stderr_fd.seek(0, os.SEEK_END) + # Open the log files for appending + stdout_fd = open(fuzzer_stdout, "a") + stderr_fd = open(fuzzer_stderr, "a") # Play nice with make's jobserver. # See https://www.gnu.org/software/make/manual/html_node/POSIX-Jobserver.html#POSIX-Jobserver # noqa @@ -422,12 +423,6 @@ def main(argv): p = None try: - log( - "Running {} -C {} run (with MAKEFLAGS='{}')", - make_cmd, - fuzzer_dir, - make_flags, - ) p = subprocess.Popen( [make_cmd, '-C', fuzzer_dir, 'run'], stdin=None, @@ -474,6 +469,7 @@ def main(argv): retcode = -1 p.kill() p.wait() + log("Warning: Killed program which should have been dead!") except Exception: tb = io.StringIO() traceback.print_exc(file=tb) @@ -490,8 +486,8 @@ def main(argv): time_end = datetime.utcnow() if retcode != 0: - # Log the last 100 lines of stderr on a failure - error_log = "\n".join(last_lines(open(fuzzer_stderr), 100)) + # Log the last 10,000 lines of stderr on a failure + error_log = "\n".join(last_lines(open(fuzzer_stderr), 10000)) log( """\ Failed @ {time_end} with exit code: {retcode} From d21433b3de1045342fd4f3eb3286af2923df9bed Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 16:58:50 -0800 Subject: [PATCH 07/16] Fixing gitignore. Signed-off-by: Tim 'mithro' Ansell --- .gitignore | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/.gitignore b/.gitignore index 95264834..b8811137 100644 --- a/.gitignore +++ b/.gitignore @@ -1,7 +1,7 @@ -/env/ -/build/ -/logs/ -/database/ +env +build +logs +database .Xil **/specimen_* **/output From a82882a4c0fd9480e12a48a80cbe02882bf1a50a Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 21:27:45 -0800 Subject: [PATCH 08/16] Always print minutes if displaying hours. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index f21c4648..82eba02c 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -31,11 +31,11 @@ def pretty_timedelta_str(d): '2m05s' >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5)) - '5h' + '5h00m' Once we get to displaying hours, we don't bother displaying seconds. >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5 + 1)) - '5h' + '5h00m' >>> pretty_timedelta_str(timedelta( ... seconds=secs_in_hour * 5 + secs_in_min * 2 + 1)) @@ -55,7 +55,7 @@ def pretty_timedelta_str(d): ts -= hours * secs_in_hour mins = int(ts / secs_in_min) - if mins > 0: + if mins > 0 or hours > 0: if hours > 0: bits.append("{:02d}m".format(mins)) else: From 09ae28be13f7f00bbf859c256081e50b0b704f26 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 21:56:05 -0800 Subject: [PATCH 09/16] Adding timestamp to log line output. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 82eba02c..9f6130a3 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -124,8 +124,11 @@ class Logger: running_for = time_log - self.time_start msg = msg.format(*args, **kw) - log_prefix = "{:s} - {:>5s}: ".format( - self.fuzzer, pretty_timedelta_str(running_for)) + log_prefix = "{:s} - {:s} - {:>5s}: ".format( + time_log.isoformat(), + self.fuzzer, + pretty_timedelta_str(running_for), + ) msg = "\n".join(log_prefix + x for x in msg.splitlines()) print(msg, flush=True) From 4f8ba05073ff3d4cadea840f9b6d82b5469302e4 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Tue, 5 Feb 2019 21:56:26 -0800 Subject: [PATCH 10/16] Use a class rather than a global. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 80 +++++++++++++++++++++---------------------- 1 file changed, 40 insertions(+), 40 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 9f6130a3..ed4e19c2 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -228,51 +228,51 @@ def get_load(): return a1 / cpus * 100.0, a5 / cpus * 100.0, a15 / cpus * 100.0 -_pstree_features = None +class PsTree: + _pstree_features = None + @classmethod + def get_features(cls): + if cls._pstree_features is None: + cls._pstree_features = [] + for f in ['-T', '-l']: + try: + subprocess.check_output( + "pstree {}".format(f), + stderr=subprocess.STDOUT, + shell=True, + ) + cls._pstree_features.append(f) + except subprocess.CalledProcessError: + continue + return cls._pstree_features -def get_pstree_features(): - global _pstree_features - if _pstree_features is None: - _pstree_features = [] - for f in ['-T', '-l']: - try: - subprocess.check_output( - "pstree {}".format(f), - stderr=subprocess.STDOUT, - shell=True, - ) - _pstree_features.append(f) - except subprocess.CalledProcessError: - continue - return _pstree_features + @classmethod + def get(cls, pid): + """Get processes under current one. + Requires the pstree until be installed, otherwise returns empty string. + """ + p = subprocess.Popen( + "pstree {} {}".format(" ".join(cls.get_features()), pid), + shell=True, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + stdin=subprocess.DEVNULL, + universal_newlines=True, + ) + stdout, stderr = p.communicate() -def get_pstree(pid): - """Get processes under current one. + # Special case segfaults. + if 'Segmentation fault' in stderr: + stderr = '' + stdout = '(result too big, pstree segfaulted.)' - Requires the pstree until be installed, otherwise returns empty string. - """ - p = subprocess.Popen( - "pstree {} {}".format(" ".join(get_pstree_features()), pid), - shell=True, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - stdin=subprocess.DEVNULL, - universal_newlines=True, - ) - stdout, stderr = p.communicate() + # If no error, just return stdout + if not stderr: + return stdout - # Special case segfaults. - if 'Segmentation fault' in stderr: - stderr = '' - stdout = '(result too big, pstree segfaulted.)' - - # If no error, just return stdout - if not stderr: - return stdout - - return "{}\n{}".format(stdout, stderr) + return "{}\n{}".format(stdout, stderr) def should_run_submake(make_flags): @@ -453,7 +453,7 @@ def main(argv): log( "Still running (1m:{:0.2f}%, 5m:{:0.2f}%, 15m:{:0.2f}%).\n{}", *get_load(), - get_pstree(p.pid), + PsTree.get(p.pid), ) except (Exception, KeyboardInterrupt, SystemExit): retcode = -1 From 772c5cad448d1ce2af19b5e7b1befd726ef32a1e Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 01:29:55 -0800 Subject: [PATCH 11/16] Add success trailer too. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index ed4e19c2..99b16b3a 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -513,7 +513,8 @@ Succeeded! @ {} -------------------------------------------------------------------------- {} -------------------------------------------------------------------------- -""", time_end.isoformat(), success_log) +Succeeded! @ {} +""", time_end.isoformat(), success_log, time_end.isoformat()) logger.flush() return retcode From fa2bf16acc03b978cb630bb8c3f95dcb189d0bf9 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 15:36:11 -0800 Subject: [PATCH 12/16] Add retries to run_fuzzer.py Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 77 ++++++++++++++++++++++++++++--------------- 1 file changed, 51 insertions(+), 26 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 99b16b3a..8731279f 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -333,51 +333,69 @@ def should_run_submake(make_flags): def main(argv): - fuzzers = os.path.abspath(os.path.dirname(__file__)) + fuzzers_dir = os.path.abspath(os.path.dirname(__file__)) parser = argparse.ArgumentParser(description=__doc__) parser.add_argument("fuzzer", help="fuzzer to run") + parser.add_argument( + "--retries", + type=int, + default=5, + help="Retry a failed fuzzer n times.", + ) args = parser.parse_args() - make_cmd = os.environ.get('MAKE', 'make') - make_flags = os.environ.get('MAKEFLAGS', '') - - # Should run things? - if not should_run_submake(make_flags): - return 0 - - time_start = datetime.utcnow() - # Setup the logger with flush=False, it should be safe to use in a signal # handler. - fuzzer_length = max(len(f) for f in os.listdir(fuzzers)) - logger = Logger(args.fuzzer, time_start, fuzzer_length) - - def log(msg, *a, **k): - logger.log(msg, a, k, flush=True) + fuzzer_length = max(len(f) for f in os.listdir(fuzzers_dir)) + logger = Logger(args.fuzzer, datetime.utcnow(), fuzzer_length) # Need a signal handler on SIGCHLD otherwise get_resource doesn't return # anything. signal.signal(signal.SIGCHLD, lambda sig, frame: None) - fuzzer_dir = os.path.join(fuzzers, args.fuzzer) + fuzzer_dir = os.path.join(fuzzers_dir, args.fuzzer) assert os.path.exists(fuzzer_dir), fuzzer_dir - # FIXME: The fuzzer output directory should be different from the top level - # fuzzer directory. - fuzzer_logdir = os.path.join(fuzzer_dir, "logs") - if not os.path.exists(fuzzer_logdir): - os.makedirs(fuzzer_logdir) - assert os.path.exists(fuzzer_logdir) - fuzzer_runok = os.path.join(fuzzer_logdir, "run.ok") + exit_code = -1 + for retry_count in range(0, args.retries): + logger.log('Running fuzzer attempt: {}', [retry_count]) + exit_code = run_fuzzer(args.fuzzer, fuzzer_dir, logger) + if exit_code <= 0: + break + logger.log('WARNING: Fuzzer failed!') + return exit_code + + +def run_fuzzer(fuzzer_name, fuzzer_dir, logger): + def log(msg, *a, **k): + logger.log(msg, a, k, flush=True) + + make_cmd = os.environ.get('MAKE', 'make') + make_flags = os.environ.get('MAKEFLAGS', '') + # Should run things? + if not should_run_submake(make_flags): + return 0 + + fuzzer_runok = os.path.join(fuzzer_dir, "run.ok") if os.path.exists(fuzzer_runok): last_modified = datetime.fromtimestamp(os.stat(fuzzer_runok).st_mtime) log( "Skipping as run.ok exists (updated @ {})", last_modified.isoformat()) - else: - log("Starting @ {}", time_start.isoformat()) + + return 0 + + time_start = datetime.utcnow() + log("Starting @ {}", time_start.isoformat()) + + # FIXME: The fuzzer output directory should be different from the top level + # fuzzer directory. + fuzzer_logdir = os.path.join(fuzzer_dir, "logs") + if not os.path.exists(fuzzer_logdir): + os.makedirs(fuzzer_logdir) + assert os.path.exists(fuzzer_logdir) running_msg = "Running {} -C {} run (with MAKEFLAGS='{}')".format( make_cmd, @@ -462,8 +480,14 @@ def main(argv): log(tb.getvalue()) # Prevent Ctrl-C so we exit properly... - signal.signal(signal.SIGINT, lambda sig, frame: logger.log("Dieing!")) + old_sigint_handler = signal.getsignal(signal.SIGINT) + def log_die(sig, frame): + logger.log("Dieing!") + + signal.signal(signal.SIGINT, log_die) + + # Cleanup child process if they haven't already died. try: if p is not None: try: @@ -517,6 +541,7 @@ Succeeded! @ {} """, time_end.isoformat(), success_log, time_end.isoformat()) logger.flush() + signal.signal(signal.SIGINT, old_sigint_handler) return retcode From 80f3f0ec04b6025d17a25f53f8758aea9c3a7842 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 16:23:36 -0800 Subject: [PATCH 13/16] Adding support for writing junit.xml files. * Fixes #494. * Includes multiple runs in output. * Includes stdout / stderr in output. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 64 +++++++++++++++++++++++++++++++++++-------- requirements.txt | 1 + 2 files changed, 53 insertions(+), 12 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 8731279f..5abeaab8 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -14,6 +14,8 @@ import subprocess import sys import traceback +import junit_xml + secs_in_min = 60 secs_in_hour = 60 * secs_in_min @@ -357,17 +359,50 @@ def main(argv): fuzzer_dir = os.path.join(fuzzers_dir, args.fuzzer) assert os.path.exists(fuzzer_dir), fuzzer_dir + fuzzer_logdir = os.path.join(fuzzer_dir, "logs") + if not os.path.exists(fuzzer_logdir): + os.makedirs(fuzzer_logdir) + assert os.path.exists(fuzzer_logdir) + exit_code = -1 + test_cases = [] for retry_count in range(0, args.retries): logger.log('Running fuzzer attempt: {}', [retry_count]) - exit_code = run_fuzzer(args.fuzzer, fuzzer_dir, logger) + exit_code, test_case = run_fuzzer( + args.fuzzer, + fuzzer_dir, + fuzzer_logdir, + logger, + ) + if test_case: + test_cases.append(test_case) if exit_code <= 0: break logger.log('WARNING: Fuzzer failed!') + + if test_cases: + pretty = True + for i, tc in enumerate(test_cases): + tc.name = "Run {}".format(i) + if tc.stdout.startswith('file://'): + pretty = False + with open(tc.stdout[7:]) as fd: + tc.stdout = fd.read() + + if tc.stderr.startswith('file://'): + pretty = False + with open(tc.stderr[7:]) as fd: + tc.stderr = fd.read() + + ts = junit_xml.TestSuite(args.fuzzer, test_cases) + tsfilename = os.path.join(fuzzer_logdir, 'sponge_log.xml') + with open(tsfilename, 'w') as f: + junit_xml.TestSuite.to_file(f, [ts], prettyprint=pretty) + return exit_code -def run_fuzzer(fuzzer_name, fuzzer_dir, logger): +def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): def log(msg, *a, **k): logger.log(msg, a, k, flush=True) @@ -375,7 +410,7 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, logger): make_flags = os.environ.get('MAKEFLAGS', '') # Should run things? if not should_run_submake(make_flags): - return 0 + return 0, None fuzzer_runok = os.path.join(fuzzer_dir, "run.ok") if os.path.exists(fuzzer_runok): @@ -385,18 +420,11 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, logger): "Skipping as run.ok exists (updated @ {})", last_modified.isoformat()) - return 0 + return 0, None time_start = datetime.utcnow() log("Starting @ {}", time_start.isoformat()) - # FIXME: The fuzzer output directory should be different from the top level - # fuzzer directory. - fuzzer_logdir = os.path.join(fuzzer_dir, "logs") - if not os.path.exists(fuzzer_logdir): - os.makedirs(fuzzer_logdir) - assert os.path.exists(fuzzer_logdir) - running_msg = "Running {} -C {} run (with MAKEFLAGS='{}')".format( make_cmd, fuzzer_dir, @@ -512,7 +540,19 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, logger): log("Finishing ({}).", get_usage()) time_end = datetime.utcnow() + + test_case = junit_xml.TestCase( + name=fuzzer_name, + timestamp=time_start.timestamp(), + elapsed_sec=(time_end - time_start).total_seconds(), + stdout='file://' + fuzzer_stdout, + stderr='file://' + fuzzer_stderr, + ) + if retcode != 0: + test_case.add_failure_info( + 'Fuzzer failed with exit code: {}'.format(retcode), ) + # Log the last 10,000 lines of stderr on a failure error_log = "\n".join(last_lines(open(fuzzer_stderr), 10000)) log( @@ -542,7 +582,7 @@ Succeeded! @ {} logger.flush() signal.signal(signal.SIGINT, old_sigint_handler) - return retcode + return retcode, test_case if __name__ == "__main__": diff --git a/requirements.txt b/requirements.txt index 38eeb09b..fb3b7322 100644 --- a/requirements.txt +++ b/requirements.txt @@ -1,6 +1,7 @@ fasm futures intervaltree +junit-xml numpy parse progressbar2 From ec6be41482b4e13f5d1dd5822ea75601cbaf4b84 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 21:57:44 -0800 Subject: [PATCH 14/16] Don't close jobserver fd so retries work. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 5abeaab8..50b198a6 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -465,10 +465,9 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): # Make sure the file descriptors exist.. job_rd_fd = os.fdopen(int(job_rd), 'rb', 0) + assert job_rd_fd job_wr_fd = os.fdopen(int(job_wr), 'rb', 0) - else: - job_rd_fd = None - job_wr_fd = None + assert job_wr_fd p = None try: @@ -481,12 +480,6 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): # control. close_fds=False) - # Close the jobserver files if they were found. - if job_rd_fd: - job_rd_fd.close() - if job_wr_fd: - job_wr_fd.close() - while True: try: retcode = p.wait(timeout=10) From 7c5103e7f35fb04ee5095599177bf6381309ff44 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 22:15:28 -0800 Subject: [PATCH 15/16] Only save the last 1000 lines to XML file. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 50b198a6..62fbc6b4 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -386,13 +386,13 @@ def main(argv): tc.name = "Run {}".format(i) if tc.stdout.startswith('file://'): pretty = False - with open(tc.stdout[7:]) as fd: - tc.stdout = fd.read() + tc.stdout = "\n".join( + last_lines(open(tc.stdout[7:]), 1000)) if tc.stderr.startswith('file://'): pretty = False - with open(tc.stderr[7:]) as fd: - tc.stderr = fd.read() + tc.stderr = "\n".join( + last_lines(open(tc.stderr[7:]), 1000)) ts = junit_xml.TestSuite(args.fuzzer, test_cases) tsfilename = os.path.join(fuzzer_logdir, 'sponge_log.xml') From c590cce721da64c1965b460e4a472e93bf1b66c4 Mon Sep 17 00:00:00 2001 From: Tim 'mithro' Ansell Date: Wed, 6 Feb 2019 22:37:45 -0800 Subject: [PATCH 16/16] Write each run into seperate file. Signed-off-by: Tim 'mithro' Ansell --- fuzzers/run_fuzzer.py | 53 +++++++++++++++++++------------------------ 1 file changed, 23 insertions(+), 30 deletions(-) diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py index 62fbc6b4..7d2f2e21 100755 --- a/fuzzers/run_fuzzer.py +++ b/fuzzers/run_fuzzer.py @@ -365,40 +365,18 @@ def main(argv): assert os.path.exists(fuzzer_logdir) exit_code = -1 - test_cases = [] for retry_count in range(0, args.retries): logger.log('Running fuzzer attempt: {}', [retry_count]) - exit_code, test_case = run_fuzzer( + exit_code = run_fuzzer( args.fuzzer, fuzzer_dir, fuzzer_logdir, logger, ) - if test_case: - test_cases.append(test_case) if exit_code <= 0: break logger.log('WARNING: Fuzzer failed!') - if test_cases: - pretty = True - for i, tc in enumerate(test_cases): - tc.name = "Run {}".format(i) - if tc.stdout.startswith('file://'): - pretty = False - tc.stdout = "\n".join( - last_lines(open(tc.stdout[7:]), 1000)) - - if tc.stderr.startswith('file://'): - pretty = False - tc.stderr = "\n".join( - last_lines(open(tc.stderr[7:]), 1000)) - - ts = junit_xml.TestSuite(args.fuzzer, test_cases) - tsfilename = os.path.join(fuzzer_logdir, 'sponge_log.xml') - with open(tsfilename, 'w') as f: - junit_xml.TestSuite.to_file(f, [ts], prettyprint=pretty) - return exit_code @@ -410,7 +388,7 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): make_flags = os.environ.get('MAKEFLAGS', '') # Should run things? if not should_run_submake(make_flags): - return 0, None + return 0 fuzzer_runok = os.path.join(fuzzer_dir, "run.ok") if os.path.exists(fuzzer_runok): @@ -420,7 +398,7 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): "Skipping as run.ok exists (updated @ {})", last_modified.isoformat()) - return 0, None + return 0 time_start = datetime.utcnow() log("Starting @ {}", time_start.isoformat()) @@ -534,20 +512,36 @@ def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger): time_end = datetime.utcnow() + error_log = "\n".join(last_lines(open(fuzzer_stderr), 10000)) + success_log = "\n".join(last_lines(open(fuzzer_stdout), 100)) + + # Find the next X_sponge_log.xml file name... + for i in range(0, 100): + tsfilename = os.path.join(fuzzer_logdir, '{}_sponge_log.xml'.format(i)) + if not os.path.exists(tsfilename): + break + test_case = junit_xml.TestCase( name=fuzzer_name, timestamp=time_start.timestamp(), elapsed_sec=(time_end - time_start).total_seconds(), - stdout='file://' + fuzzer_stdout, - stderr='file://' + fuzzer_stderr, + stdout=success_log, + stderr=error_log, ) + if retcode != 0: + test_case.add_failure_info( + 'Fuzzer failed with exit code: {}'.format(retcode)) + + with open(tsfilename, 'w') as f: + ts = junit_xml.TestSuite(fuzzer_name, [test_case]) + junit_xml.TestSuite.to_file(f, [ts]) + if retcode != 0: test_case.add_failure_info( 'Fuzzer failed with exit code: {}'.format(retcode), ) # Log the last 10,000 lines of stderr on a failure - error_log = "\n".join(last_lines(open(fuzzer_stderr), 10000)) log( """\ Failed @ {time_end} with exit code: {retcode} @@ -563,7 +557,6 @@ Failed @ {time_end} with exit code: {retcode} else: # Log the last 100 lines of a successful run - success_log = "\n".join(last_lines(open(fuzzer_stdout), 100)) log( """\ Succeeded! @ {} @@ -575,7 +568,7 @@ Succeeded! @ {} logger.flush() signal.signal(signal.SIGINT, old_sigint_handler) - return retcode, test_case + return retcode if __name__ == "__main__":