DeforaNetworks/manticore
3
0
Fork 0
Code Releases Activity

Refactor logging (#140)

Browse Source 
* begin refactoring logging to use manticore object

* fix verbosity things

* fix logging when in scripts

* remove m.log_file now that it's no longer used

* remove unnecessary init_logging usage and unused log_debug variable

* accidentally deleted the wrong line

* re-hide init_logging

* remove old log_debug

* remove unnecessary API stuff and refactor around that

* re-introduce logging PR

* fix Popen

* lost a line in merge

* fix test_binaries

* Log to stdout instead of stderr

* implement mark's changes
This commit is contained in:
JP Smith 2017-04-19 01:21:14 -05:00 committed by GitHub
parent 65df1cbe35
commit e32701f978
5 changed files with 60 additions and 128 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

42
manticore/__main__.py
View File

@ -15,6 +15,7 @@ except ImportError:
pass pass
sys.setrecursionlimit(10000) sys.setrecursionlimit(10000)
logger = logging.getLogger('MAIN')
def parse_arguments(): def parse_arguments():
########################################################################### ###########################################################################
@ -22,8 +23,6 @@ def parse_arguments():
parser = argparse.ArgumentParser(description='Symbolically analyze a program') parser = argparse.ArgumentParser(description='Symbolically analyze a program')
parser.add_argument('--workspace', type=str, default=None, parser.add_argument('--workspace', type=str, default=None,
help='A folder name for temporaries and results. (default mcore_?????)') help='A folder name for temporaries and results. (default mcore_?????)')
parser.add_argument('--log', type=str, default='-',
help='The log filename')
parser.add_argument('--verbose', action='store_true', help='Enable debug mode.') parser.add_argument('--verbose', action='store_true', help='Enable debug mode.')
parser.add_argument('--profile', action='store_true', help='Enable profiling mode.') parser.add_argument('--profile', action='store_true', help='Enable profiling mode.')
@ -67,8 +66,6 @@ def parse_arguments():
return parsed return parsed
logger = logging.getLogger('MAIN')
def main(): def main():
args = parse_arguments() args = parse_arguments()
@ -80,9 +77,6 @@ def main():
if args.workspace: if args.workspace:
m.workspace = args.workspace m.workspace = args.workspace
if args.log:
m.log_file = args.log
if args.profile: if args.profile:
m.should_profile = args.profile m.should_profile = args.profile
@ -112,38 +106,10 @@ def main():
if args.assertions: if args.assertions:
m.load_assertions(args.assertions) m.load_assertions(args.assertions)
# logging if args.verbose:
class ContextFilter(logging.Filter): m.verbosity = 5
'''
This is a filter which injects contextual information into the log.
'''
def filter(self, record):
if hasattr(self, 'stateid') and isinstance(self.stateid, int):
record.stateid = '[%d]' % self.stateid
else: else:
record.stateid = '' m.verbosity = 1
return True
def loggerSetState(logger, stateid):
logger.filters[0].stateid = stateid
logging.basicConfig(filename = args.log,
format = '%(asctime)s: [%(process)d]%(stateid)s %(name)s:%(levelname)s: %(message)s',
level = {False:logging.INFO, True:logging.DEBUG}[args.verbose])
verbosity = {False:logging.INFO, True:logging.DEBUG}[args.verbose]
ctxfilter = ContextFilter()
for loggername in ['VISITOR', 'EXECUTOR', 'CPU', 'SMT', 'MEMORY', 'MAIN', 'MODEL']:
logging.getLogger(loggername).addFilter(ctxfilter)
logging.getLogger(loggername).setLevel(verbosity)
logging.getLogger(loggername).setState = types.MethodType(loggerSetState, logging.getLogger(loggername))
logging.getLogger('SMT').setLevel(logging.INFO)
logging.getLogger('MEMORY').setLevel(logging.INFO)
#logging.getLogger('CPU').setLevel(logging.INFO)
logging.getLogger('LIBC').setLevel(logging.INFO)
logger.info('Loading program: {}'.format(args.programs)) logger.info('Loading program: {}'.format(args.programs))
logger.info('Workspace: {}'.format(m.workspace)) logger.info('Workspace: {}'.format(m.workspace))

60
manticore/manticore.py
View File

@ -25,7 +25,6 @@ from .utils.helpers import issymbolic
logger = logging.getLogger('MANTICORE') logger = logging.getLogger('MANTICORE')
def makeDecree(args): def makeDecree(args):
constraints = ConstraintSet() constraints = ConstraintSet()
model = decree.SDecree(constraints, ','.join(args.programs)) model = decree.SDecree(constraints, ','.join(args.programs))
@ -139,6 +138,7 @@ class Manticore(object):
:type args: list[str] :type args: list[str]
''' '''
def __init__(self, binary_path, args=None): def __init__(self, binary_path, args=None):
assert os.path.isfile(binary_path) assert os.path.isfile(binary_path)
@ -165,8 +165,6 @@ class Manticore(object):
self._hooks = {} self._hooks = {}
self._running = False self._running = False
self._arch = None self._arch = None
self._log_debug = False
self._log_file = '/dev/stdout'
self._concrete_data = '' self._concrete_data = ''
self._dumpafter = 0 self._dumpafter = 0
self._maxstates = 0 self._maxstates = 0
@ -185,14 +183,6 @@ class Manticore(object):
self._init_logging() self._init_logging()
def _init_logging(self): def _init_logging(self):
fmt_str = '%(asctime)s: [%(process)d]%(stateid)s %(name)s:%(levelname)s: %(message)s'
if self._log_debug:
log_level = logging.DEBUG
else:
log_level = logging.WARNING
logging.basicConfig(filename=self._log_file, format=fmt_str, level=log_level)
def loggerSetState(logger, stateid): def loggerSetState(logger, stateid):
logger.filters[0].stateid = stateid logger.filters[0].stateid = stateid
@ -209,27 +199,16 @@ class Manticore(object):
return True return True
ctxfilter = ContextFilter() ctxfilter = ContextFilter()
for name, logger in logging.Logger.manager.loggerDict.items():
logger.addFilter(ctxfilter)
logger.setLevel(log_level)
logger.setState = types.MethodType(loggerSetState, logger)
@property logging.basicConfig(format='%(asctime)s: [%(process)d]%(stateid)s %(name)s:%(levelname)s: %(message)s', stream=sys.stdout)
def log_file(self):
return self._log_file
@log_file.setter for loggername in ['VISITOR', 'EXECUTOR', 'CPU', 'SMT', 'MEMORY', 'MAIN', 'MODEL']:
def log_file(self, path): logging.getLogger(loggername).addFilter(ctxfilter)
if self._log_file == path: logging.getLogger(loggername).setState = types.MethodType(loggerSetState, logging.getLogger(loggername))
return
if path == '-':
path = '/dev/stdout'
self._log_file = path
self._init_logging()
logging.getLogger('SMT').setLevel(logging.INFO)
logging.getLogger('MEMORY').setLevel(logging.INFO)
logging.getLogger('LIBC').setLevel(logging.INFO)
# XXX(yan): args is a temporary hack to include while we continue moving # XXX(yan): args is a temporary hack to include while we continue moving
# non-Linux platforms to new-style arg handling. # non-Linux platforms to new-style arg handling.
@ -281,19 +260,6 @@ class Manticore(object):
def maxstorage(self, max_storage): def maxstorage(self, max_storage):
self._maxstorage = max_storage self._maxstorage = max_storage
@property
def log_debug(self):
return self._log_debug
@log_debug.setter
def log_debug(self, debug):
if self._log_debug == debug:
return
self._log_debug = debug
self._init_logging()
@property @property
def verbosity(self): def verbosity(self):
''' '''
@ -305,11 +271,11 @@ class Manticore(object):
@verbosity.setter @verbosity.setter
def verbosity(self, setting): def verbosity(self, setting):
levels = [[], levels = [[],
[('EXECUTOR', logging.INFO)], [('MAIN', logging.INFO), ('EXECUTOR', logging.INFO)],
[('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG)], [('MAIN', logging.INFO), ('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG)],
[('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG)], [('MAIN', logging.INFO), ('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG)],
[('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG)], [('MAIN', logging.INFO), ('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG)],
[('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG), ('SMTLIB', logging.DEBUG)]] [('MAIN', logging.INFO), ('EXECUTOR', logging.DEBUG), ('MODEL', logging.DEBUG), ('MEMORY', logging.DEBUG), ('CPU', logging.DEBUG), ('SMTLIB', logging.DEBUG)]]
# Takes a value and ensures it's in a certain range # Takes a value and ensures it's in a certain range
def clamp(val, minimum, maximum): def clamp(val, minimum, maximum):
return sorted((minimum, val, maximum))[1] return sorted((minimum, val, maximum))[1]

16
tests/test_binaries.py
View File

@ -20,9 +20,10 @@ class IntegrationTest(unittest.TestCase):
# Remove the directory after the test # Remove the directory after the test
shutil.rmtree(self.test_dir) shutil.rmtree(self.test_dir)
def _runWithTimeout(self, procargs, timeout=1200): def _runWithTimeout(self, procargs, logfile, timeout=1200):
po = subprocess.Popen(procargs) with open(os.path.join(os.pardir, logfile), "w") as output:
po = subprocess.Popen(procargs, stdout=output)
secs_used = 0 secs_used = 0
while po.poll() is None and secs_used < timeout: while po.poll() is None and secs_used < timeout:
@ -43,13 +44,13 @@ class IntegrationTest(unittest.TestCase):
self.assertEqual(hashlib.md5(data).hexdigest() , '00fb23e47831a1054ca4a74656035472') self.assertEqual(hashlib.md5(data).hexdigest() , '00fb23e47831a1054ca4a74656035472')
workspace = '%s/workspace'%self.test_dir workspace = '%s/workspace'%self.test_dir
t = time.time() t = time.time()
with open(os.path.join(os.pardir, '%s/output.log'%self.test_dir), "w") as output:
po = subprocess.call(['python', '-m', 'manticore', po = subprocess.call(['python', '-m', 'manticore',
'--log', '%s/output.log'%self.test_dir,
'--workspace', workspace, '--workspace', workspace,
'--timeout', '1', '--timeout', '1',
'--procs', '4', '--procs', '4',
filename, filename,
'+++++++++']) '+++++++++'], stdout=output)
self.assertTrue(time.time()-t < 20) self.assertTrue(time.time()-t < 20)
@ -66,13 +67,13 @@ class IntegrationTest(unittest.TestCase):
workspace = '%s/workspace'%self.test_dir workspace = '%s/workspace'%self.test_dir
assertions = '%s/assertions.txt'%self.test_dir assertions = '%s/assertions.txt'%self.test_dir
file(assertions,'w').write('0x0000000000401003 ZF == 1') file(assertions,'w').write('0x0000000000401003 ZF == 1')
with open(os.path.join(os.pardir, '%s/output.log'%self.test_dir), "w") as output:
self._runWithTimeout(['python', SE, self._runWithTimeout(['python', SE,
'--log', '%s/output.log'%self.test_dir,
'--workspace', workspace, '--workspace', workspace,
'--proc', '4', '--proc', '4',
'--assertions', assertions, '--assertions', assertions,
filename, filename,
'+++++++++']) '+++++++++'], stdout=output)
data = file('%s/visited.txt'%workspace,'r').read() data = file('%s/visited.txt'%workspace,'r').read()
data = '\n'.join(sorted(set(data.split('\n')))) data = '\n'.join(sorted(set(data.split('\n'))))
self.assertEqual(hashlib.md5(data).hexdigest() , 'c52d7d471ba5c94fcf59936086821a6b') self.assertEqual(hashlib.md5(data).hexdigest() , 'c52d7d471ba5c94fcf59936086821a6b')
@ -89,12 +90,11 @@ class IntegrationTest(unittest.TestCase):
self.assertEqual(hashlib.md5(data).hexdigest() , '8955a29d51c1edd39b0e53794ebcf464') self.assertEqual(hashlib.md5(data).hexdigest() , '8955a29d51c1edd39b0e53794ebcf464')
workspace = '%s/workspace'%self.test_dir workspace = '%s/workspace'%self.test_dir
self._runWithTimeout(['python', '-m', 'manticore', self._runWithTimeout(['python', '-m', 'manticore',
'--log', '%s/output.log'%self.test_dir,
'--workspace', workspace, '--workspace', workspace,
'--timeout', '20', '--timeout', '20',
'--proc', '4', '--proc', '4',
'--policy', 'uncovered', '--policy', 'uncovered',
filename]) filename], '%s/output.log'%self.test_dir)
data = file('%s/visited.txt'%workspace,'r').read() data = file('%s/visited.txt'%workspace,'r').read()
visited = len(set(data.split('\n'))) visited = len(set(data.split('\n')))

1
tests/test_driver.py
View File

@ -24,7 +24,6 @@ class ManticoreDriver(unittest.TestCase):
def testCreating(self): def testCreating(self):
m = Manticore('/bin/ls') m = Manticore('/bin/ls')
m.log_debug = False
m.log_file = '/dev/null' m.log_file = '/dev/null'
def test_issymbolic(self): def test_issymbolic(self):

7
tests/test_memdumps.py
View File

@ -38,7 +38,8 @@ class IntegrationTest(unittest.TestCase):
def _runWithTimeout(self, procargs, timeout=600): def _runWithTimeout(self, procargs, timeout=600):
po = subprocess.Popen(procargs) with open(os.path.join(os.pardir, "logfile"), "w") as output:
po = subprocess.Popen(procargs, stdout=output)
secs_used = 0 secs_used = 0
while po.poll() is None and secs_used < timeout: while po.poll() is None and secs_used < timeout:
@ -65,12 +66,12 @@ class IntegrationTest(unittest.TestCase):
dumpfile = os.path.join(dumpdir, params['dump']) dumpfile = os.path.join(dumpdir, params['dump'])
args = ['manticore', '--workspace', workspace, '--log', logfile, dumpfile] args = ['manticore', '--workspace', workspace, dumpfile]
for k,v in params.iteritems(): for k,v in params.iteritems():
if k.startswith("--"): if k.startswith("--"):
args.extend([k, v.format(dumpdir=dumpdir, workspace=workspace)]) args.extend([k, v.format(dumpdir=dumpdir, workspace=workspace)])
self._runWithTimeout(args) self._runWithTimeout(args, logfile)
efile = os.path.join(dumpdir, params['expected']) efile = os.path.join(dumpdir, params['expected'])
expected = self._loadVisitedSet(efile) expected = self._loadVisitedSet(efile)