luke
/
prjxray
mirror of https://github.com/openXC7/prjxray.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity
prjxray/fuzzers/run_fuzzer.py

693 lines
19 KiB
Python
Executable File
Raw Blame History

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
#
# Copyright (C) 2017-2020 The Project X-Ray Authors.
#
# Use of this source code is governed by a ISC-style
# license that can be found in the LICENSE file or at
# https://opensource.org/licenses/ISC
#
# SPDX-License-Identifier: ISC
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
from utils.create_environment import get_environment_variables
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!")
2001-11-01T00:00:10 - fuzz - 10s: Test!
>>> l.log("Format {} {t}", [1,], {'t': 2})
2001-11-01T00:00:10 - fuzz - 10s: Format 1 2
>>> l.log('''\\
... Line 1
... Line 2
... Line 3
... ''')
2001-11-01T00:00:10 - fuzz - 10s: Line 1
2001-11-01T00:00:10 - fuzz - 10s: Line 2
2001-11-01T00:00:10 - 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)
time_log = time_log.replace(microsecond=0)
log_prefix = "{:s} - {}/{:s} - {:>5s}: ".format(
time_log.isoformat(),
os.environ['XRAY_PART'],
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 mem_convert(s):
"""
>>> mem_convert('62G')
62000000000.0
>>> mem_convert('62M')
62000000.0
>>> mem_convert('62B')
62.0
"""
units = {
'Gi': pow(2, 30),
'Mi': pow(2, 20),
'Ki': pow(2, 10),
'G': 1e9,
'M': 1e6,
'K': 1e3,
'B': 1,
}
u = '',
m = 1
for u, m in units.items():
if s.endswith(u):
break
v = float(s[:-len(u)])
v = v * m
return v
def get_memory(memstr=None):
r"""
>>> import pprint
>>> pprint.pprint(get_memory('''\
... total used free shared buff/cache available
... Mem: 62G 19G 4.8G 661M 38G 42G
... Swap: 0B 0B 0B
... '''))
{'mem': {'available': 42000000000.0,
'buff/cache': 38000000000.0,
'free': 4800000000.0,
'shared': 661000000.0,
'total': 62000000000.0,
'used': 19000000000.0},
'swap': {'free': 0.0, 'total': 0.0, 'used': 0.0}}
"""
if memstr is None:
memstr = subprocess.check_output(
'free -mh', shell=True).decode("utf-8")
lines = [x.split() for x in memstr.strip().splitlines()]
lines[0].insert(0, 'type:')
for l in lines:
l[0] = l[0][:-1].lower()
headers = lines[0][1:]
lines = lines[1:]
memory = {}
for l in lines:
t, l = l[0], l[1:]
d = {}
for k, v in zip(headers, l):
d[k] = mem_convert(v)
memory[t] = d
return memory
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=0,
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_{}".format(os.environ['XRAY_PART']))
if not os.path.exists(fuzzer_logdir):
os.makedirs(fuzzer_logdir)
assert os.path.exists(fuzzer_logdir)
# Update the environment for a specific part
environment = get_environment_variables()
for key, value in environment.items():
os.environ[key] = value
exit_code = -1
args.retries += 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,
will_retry=retry_count < (args.retries - 1),
)
if exit_code <= 0:
break
logger.log('WARNING: Fuzzer failed!')
return exit_code
def run_fuzzer(fuzzer_name, fuzzer_dir, fuzzer_logdir, logger, will_retry):
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".format(os.environ['XRAY_PART']))
if os.path.exists(fuzzer_runok):
last_modified = datetime.fromtimestamp(os.stat(fuzzer_runok).st_mtime)
log(
"Skipping as run.{}.ok exists (updated @ {})",
os.environ['XRAY_PART'], last_modified.isoformat())
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()).replace(":", "-")
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
job_fds = []
if '--jobserver-fds' in make_flags or '--jobserver-auth' in make_flags:
job_re = re.search(
'--jobserver-(?:fds|auth)=([0-9]+),([0-9]+)', make_flags)
assert job_re, make_flags
job_rd, job_wr = job_re.groups()
# Make copies of jobserver FDs in case a retry is needed.
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)
job_fds.append(job_rd)
job_fds.append(job_wr)
p = None
try:
p = subprocess.Popen(
[make_cmd, '-C', fuzzer_dir, 'run'],
stdin=None,
stdout=stdout_fd,
stderr=stderr_fd,
pass_fds=job_fds,
)
while True:
try:
retcode = p.wait(timeout=10)
p = None
except subprocess.TimeoutExpired:
retcode = None
if retcode is not None:
break
mem = get_memory()['mem']
log(
"Still running (1m:{:0.2f}%, 5m:{:0.2f}%, 15m:{:0.2f}% Mem:{:0.1f}Gi used, {:0.1f}Gi free).\n{}",
*get_load(),
mem['used'] / 1e9,
mem['available'] /
1e9, # Using available so the numbers add up.
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}
--------------------------------------------------------------------------
- STDOUT (see {stdout_fname} for full log):
--------------------------------------------------------------------------
{stdout_log}
--------------------------------------------------------------------------
- STDERR (see {stderr_fname} for full log):
--------------------------------------------------------------------------
{stderr_log}
--------------------------------------------------------------------------
!Failed! @ {time_end} with exit code: {retcode}
--------------------------------------------------------------------------
""",
retcode=retcode,
stdout_fname=fuzzer_stdout,
stdout_log='\n'.join(last_lines(open(fuzzer_stdout), 1000)),
stderr_fname=fuzzer_stderr,
stderr_log='\n'.join(last_lines(open(fuzzer_stderr), 1000)),
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))
Reference in New Issue View Git Blame Copy Permalink