diff --git a/.gitignore b/.gitignore index f9585e4e..b8811137 100644 --- a/.gitignore +++ b/.gitignore @@ -1,6 +1,7 @@ -/env/ -/build/ -/database/ +env +build +logs +database .Xil **/specimen_* **/output 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 diff --git a/fuzzers/Makefile b/fuzzers/Makefile index be8c70d8..20754216 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,36 @@ 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 -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) -C $(1) run + +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,)) 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 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 - diff --git a/fuzzers/run_fuzzer.py b/fuzzers/run_fuzzer.py new file mode 100755 index 00000000..7d2f2e21 --- /dev/null +++ b/fuzzers/run_fuzzer.py @@ -0,0 +1,579 @@ +#!/usr/bin/env python3 + +from datetime import datetime, timedelta + +import argparse +import collections +import io +import os +import os.path +import re +import resource +import signal +import subprocess +import sys +import traceback + +import junit_xml + +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)) + '5h00m' + + Once we get to displaying hours, we don't bother displaying seconds. + >>> pretty_timedelta_str(timedelta(seconds=secs_in_hour * 5 + 1)) + '5h00m' + + >>> 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 or hours > 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 = collections.deque() + + 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.popleft() + 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} - {: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) + + +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 = collections.deque(['']) + # 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 list(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 + + +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 + + @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() + + # 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) + + +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 + + 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. + + >>> should_run_submake('') + True + + The following flags are important; + + -n == --dry-run + + >>> should_run_submake('n') + False + >>> should_run_submake('n --blah') + False + >>> should_run_submake('--blah n') + False + >>> should_run_submake('--blah') + True + >>> should_run_submake('--random') + True + + -q == --question + + >>> should_run_submake('q') + False + >>> should_run_submake('q --blah') + False + >>> should_run_submake('--blah q') + False + >>> should_run_submake('--blah') + True + >>> should_run_submake('--random') + True + + Both --dry-run and --question + + >>> should_run_submake('qn') + False + >>> should_run_submake('nq') + False + >>> should_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_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() + + # 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_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_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 + for retry_count in range(0, args.retries): + logger.log('Running fuzzer attempt: {}', [retry_count]) + exit_code = run_fuzzer( + args.fuzzer, + fuzzer_dir, + fuzzer_logdir, + logger, + ) + if exit_code <= 0: + break + logger.log('WARNING: Fuzzer failed!') + + return exit_code + + +def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, 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()) + + return 0 + + time_start = datetime.utcnow() + 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_logdir, "stdout" + log_suffix) + fuzzer_stderr = os.path.join(fuzzer_logdir, "stderr" + log_suffix) + + # 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) + + # 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 + 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) + assert job_rd_fd + job_wr_fd = os.fdopen(int(job_wr), 'rb', 0) + assert job_wr_fd + + p = None + try: + 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) + + 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(), + PsTree.get(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... + 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: + retcode = p.wait(1) + except subprocess.TimeoutExpired: + 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) + 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() + + 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=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 + 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 + log( + """\ +Succeeded! @ {} +-------------------------------------------------------------------------- +{} +-------------------------------------------------------------------------- +Succeeded! @ {} +""", time_end.isoformat(), success_log, time_end.isoformat()) + + logger.flush() + signal.signal(signal.SIGINT, old_sigint_handler) + 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)) 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