From c9f4d1b9b807676310e7ae9179af99e726c0ee02 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 15:23:23 -0700 Subject: [PATCH 01/23] change log level when fuzzing if not specified --- src/lib/DeepState.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index b8445c2..fafeb3c 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -642,6 +642,10 @@ bool DeepState_CatchAbandoned(void) { Has to be defined here since we redefine rand in the header. */ int DeepState_Fuzz(void){ DeepState_LogFormat(DeepState_LogInfo, "Starting fuzzing"); + + if (!HAS_FLAG_log_level) { + FLAGS_log_level = 2; + } if (HAS_FLAG_seed) { srand(FLAGS_seed); From 8171e3c4604abd4104117cb7905cfd900ac55ddf Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 15:37:19 -0700 Subject: [PATCH 02/23] start on symex logging changes --- bin/deepstate/common.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 1ee596b..c649249 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -137,8 +137,12 @@ class DeepState(object): parser.add_argument( "--verbosity", default=1, type=int, - help="Verbosity level.") + help="Verbosity level for symbolic execution tool.") + parser.add_argument( + "--log_level", default=2, type=int, + help="Log level (DeepState logging).") + parser.add_argument( "binary", type=str, help="Path to the test binary to run.") @@ -240,7 +244,7 @@ class DeepState(object): self.context['stream_{}'.format(level)] = [] self.context['info'] = info - self.log_message(LOG_LEVEL_INFO, "Running {} from {}({})".format( + self.log_message(LOG_LEVEL_TRACE, "Running {} from {}({})".format( info.name, info.file_name, info.line_number)) apis = self.context['apis'] @@ -385,7 +389,7 @@ class DeepState(object): # Print out the first few input bytes to be helpful. lots_of_bytes = len(input_bytes) > 20 and " ..." or "" bytes_to_show = min(20, len(input_bytes)) - LOGGER.info("Input: {}{}".format( + LOGGER.trace("Input: {}{}".format( " ".join("{:02x}".format(b) for b in input_bytes[:bytes_to_show]), lots_of_bytes)) @@ -494,7 +498,7 @@ class DeepState(object): self.api_fail() else: info = self.context['info'] - self.log_message(LOG_LEVEL_INFO, "Passed: {}".format(info.name)) + self.log_message(LOG_LEVEL_TRACE, "Passed: {}".format(info.name)) self.pass_test() def api_crash(self): From b449111ecfec6a619f49cf3576e132146dc79a7c Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:08:48 -0700 Subject: [PATCH 03/23] set default log level in symex --- bin/deepstate/common.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index c649249..9eefc6f 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -260,6 +260,17 @@ class DeepState(object): # Create the output directory for this test case. args = self.parse_args() + + logging_levels = { + LOG_LEVEL_DEBUG: logging.DEBUG, + LOG_LEVEL_TRACE: logging.TRACE, + LOG_LEVEL_INFO: logging.INFO, + LOG_LEVEL_WARNING: logging.WARNING, + LOG_LEVEL_ERROR: logging.ERROR, + LOG_LEVEL_FATAL: logging.CRITICAL + } + LOGGER.setLevel(logging_levels[args.log_level]) + if args.output_test_dir is not None: test_dir = os.path.join(args.output_test_dir, os.path.basename(info.file_name), From 1bfaeaac68b0bc9e97060bdfb1f67a806cb07a23 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:13:19 -0700 Subject: [PATCH 04/23] assign LOGGING.trace --- bin/deepstate/common.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 9eefc6f..cef7216 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -45,9 +45,11 @@ LOG_LEVEL_FATAL = 6 LOGGER = logging.getLogger("deepstate") LOGGER.setLevel(logging.DEBUG) +LOGGER.trace = functools.partial(LOGGER.log, 15) + LOG_LEVEL_TO_LOGGER = { LOG_LEVEL_DEBUG: LOGGER.debug, - LOG_LEVEL_TRACE: functools.partial(LOGGER.log, 15), + LOG_LEVEL_TRACE: LOGGER.trace, LOG_LEVEL_INFO: LOGGER.info, LOG_LEVEL_WARNING: LOGGER.warning, LOG_LEVEL_ERROR: LOGGER.error, From 16de1bc68cd5e4000a22d11bedf692ba8ffbb730 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:15:08 -0700 Subject: [PATCH 05/23] assign logging.TRACE --- bin/deepstate/common.py | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index cef7216..9b71f70 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -46,6 +46,7 @@ LOGGER = logging.getLogger("deepstate") LOGGER.setLevel(logging.DEBUG) LOGGER.trace = functools.partial(LOGGER.log, 15) +logging.TRACE = 15 LOG_LEVEL_TO_LOGGER = { LOG_LEVEL_DEBUG: LOGGER.debug, From caa3d33429932ff93632c6ead9f100fc6fbcf564 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 15:23:23 -0700 Subject: [PATCH 06/23] change log level when fuzzing if not specified --- src/lib/DeepState.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index bdd06de..ecd3b98 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -642,6 +642,10 @@ bool DeepState_CatchAbandoned(void) { Has to be defined here since we redefine rand in the header. */ int DeepState_Fuzz(void){ DeepState_LogFormat(DeepState_LogInfo, "Starting fuzzing"); + + if (!HAS_FLAG_log_level) { + FLAGS_log_level = 2; + } if (HAS_FLAG_seed) { srand(FLAGS_seed); From 4bc1a3c00decb4fb889f2e4bc8ba19527836728e Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 15:37:19 -0700 Subject: [PATCH 07/23] start on symex logging changes --- bin/deepstate/common.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 1ee596b..c649249 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -137,8 +137,12 @@ class DeepState(object): parser.add_argument( "--verbosity", default=1, type=int, - help="Verbosity level.") + help="Verbosity level for symbolic execution tool.") + parser.add_argument( + "--log_level", default=2, type=int, + help="Log level (DeepState logging).") + parser.add_argument( "binary", type=str, help="Path to the test binary to run.") @@ -240,7 +244,7 @@ class DeepState(object): self.context['stream_{}'.format(level)] = [] self.context['info'] = info - self.log_message(LOG_LEVEL_INFO, "Running {} from {}({})".format( + self.log_message(LOG_LEVEL_TRACE, "Running {} from {}({})".format( info.name, info.file_name, info.line_number)) apis = self.context['apis'] @@ -385,7 +389,7 @@ class DeepState(object): # Print out the first few input bytes to be helpful. lots_of_bytes = len(input_bytes) > 20 and " ..." or "" bytes_to_show = min(20, len(input_bytes)) - LOGGER.info("Input: {}{}".format( + LOGGER.trace("Input: {}{}".format( " ".join("{:02x}".format(b) for b in input_bytes[:bytes_to_show]), lots_of_bytes)) @@ -494,7 +498,7 @@ class DeepState(object): self.api_fail() else: info = self.context['info'] - self.log_message(LOG_LEVEL_INFO, "Passed: {}".format(info.name)) + self.log_message(LOG_LEVEL_TRACE, "Passed: {}".format(info.name)) self.pass_test() def api_crash(self): From 9f8f0f0a418470a0e5adb22d7e3acbc8a7cf9088 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:08:48 -0700 Subject: [PATCH 08/23] set default log level in symex --- bin/deepstate/common.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index c649249..9eefc6f 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -260,6 +260,17 @@ class DeepState(object): # Create the output directory for this test case. args = self.parse_args() + + logging_levels = { + LOG_LEVEL_DEBUG: logging.DEBUG, + LOG_LEVEL_TRACE: logging.TRACE, + LOG_LEVEL_INFO: logging.INFO, + LOG_LEVEL_WARNING: logging.WARNING, + LOG_LEVEL_ERROR: logging.ERROR, + LOG_LEVEL_FATAL: logging.CRITICAL + } + LOGGER.setLevel(logging_levels[args.log_level]) + if args.output_test_dir is not None: test_dir = os.path.join(args.output_test_dir, os.path.basename(info.file_name), From 8ef1bd6af8b95f6fc860400db5debde3ff79fcb8 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:13:19 -0700 Subject: [PATCH 09/23] assign LOGGING.trace --- bin/deepstate/common.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 9eefc6f..cef7216 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -45,9 +45,11 @@ LOG_LEVEL_FATAL = 6 LOGGER = logging.getLogger("deepstate") LOGGER.setLevel(logging.DEBUG) +LOGGER.trace = functools.partial(LOGGER.log, 15) + LOG_LEVEL_TO_LOGGER = { LOG_LEVEL_DEBUG: LOGGER.debug, - LOG_LEVEL_TRACE: functools.partial(LOGGER.log, 15), + LOG_LEVEL_TRACE: LOGGER.trace, LOG_LEVEL_INFO: LOGGER.info, LOG_LEVEL_WARNING: LOGGER.warning, LOG_LEVEL_ERROR: LOGGER.error, From e65adca27b9ce07da1892732dfc3e0f45f8cf392 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 16:15:08 -0700 Subject: [PATCH 10/23] assign logging.TRACE --- bin/deepstate/common.py | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index cef7216..9b71f70 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -46,6 +46,7 @@ LOGGER = logging.getLogger("deepstate") LOGGER.setLevel(logging.DEBUG) LOGGER.trace = functools.partial(LOGGER.log, 15) +logging.TRACE = 15 LOG_LEVEL_TO_LOGGER = { LOG_LEVEL_DEBUG: LOGGER.debug, From 9e99978043899dda119ce68c8f58f5891aab7271 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 18:17:15 -0700 Subject: [PATCH 11/23] tests are verbose for debugging and checking output --- tests/logrun.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/logrun.py b/tests/logrun.py index 3c9c5c4..23be692 100644 --- a/tests/logrun.py +++ b/tests/logrun.py @@ -9,7 +9,7 @@ def logrun(cmd, file, timeout): sys.stderr.write(" ".join(cmd) + "\n\n") sys.stderr.flush() with open(file, 'w') as outf: - p = subprocess.Popen(cmd, stdout=outf, stderr=outf) + p = subprocess.Popen(cmd + ["--log_level", "1"], stdout=outf, stderr=outf) start = time.time() oldContents = "" lastOutput = time.time() From fec2849bfbecabde315c5a3bef8b2971d02cc51e Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Wed, 2 Jan 2019 20:16:09 -0700 Subject: [PATCH 12/23] Fix logging level in logrun, demote assumption checks --- src/include/deepstate/DeepState.h | 2 +- src/include/deepstate/DeepState.hpp | 4 ++-- tests/logrun.py | 3 ++- 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index ef57123..3364433 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -486,7 +486,7 @@ static void DeepState_InitInputFromFile(const char *path) { DeepState_Abandon("Error reading file"); } - DeepState_LogFormat(DeepState_LogInfo, + DeepState_LogFormat(DeepState_LogTrace, "Initialized test input buffer with data from `%s`", path); } diff --git a/src/include/deepstate/DeepState.hpp b/src/include/deepstate/DeepState.hpp index e4c0617..f895550 100644 --- a/src/include/deepstate/DeepState.hpp +++ b/src/include/deepstate/DeepState.hpp @@ -584,11 +584,11 @@ struct Comparer { #define ASSUME(expr) \ DeepState_Assume(expr), ::deepstate::Stream( \ - DeepState_LogInfo, true, __FILE__, __LINE__) + DeepState_LogTrace, true, __FILE__, __LINE__) #define DEEPSTATE_ASSUME_BINOP(a, b, op) \ DeepState_Assume((a op b)), ::deepstate::Stream( \ - DeepState_LogInfo, true, __FILE__, __LINE__) + DeepState_LogTrace, true, __FILE__, __LINE__) #define ASSUME_EQ(a, b) DEEPSTATE_ASSUME_BINOP(a, b, ==) #define ASSUME_NE(a, b) DEEPSTATE_ASSUME_BINOP(a, b, !=) diff --git a/tests/logrun.py b/tests/logrun.py index 23be692..cd5926f 100644 --- a/tests/logrun.py +++ b/tests/logrun.py @@ -9,7 +9,8 @@ def logrun(cmd, file, timeout): sys.stderr.write(" ".join(cmd) + "\n\n") sys.stderr.flush() with open(file, 'w') as outf: - p = subprocess.Popen(cmd + ["--log_level", "1"], stdout=outf, stderr=outf) + # We need to set log_level so we see ALL messages, for testing + p = subprocess.Popen(cmd + ["--log_level", "0"], stdout=outf, stderr=outf) start = time.time() oldContents = "" lastOutput = time.time() From 652d6355b2a2a6362cd9979f852ab651273c5814 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 11:59:55 -0700 Subject: [PATCH 13/23] More silent: nothing about test failures --- bin/deepstate/common.py | 8 +++++++- src/lib/DeepState.c | 14 +++++++++----- 2 files changed, 16 insertions(+), 6 deletions(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 9b71f70..bdb3c5e 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -359,21 +359,27 @@ class DeepState(object): test_dir = self.context['test_dir'] test_name = md5.new(input_bytes).hexdigest() + passing = False if self.context['failed']: test_name += ".fail" elif self.context['crashed']: test_name += ".crash" else: test_name += ".pass" + passing = True test_file = os.path.join(test_dir, test_name) - LOGGER.info("Saving input to {}".format(test_file)) try: with open(test_file, "wb") as f: f.write(input_bytes) except: LOGGER.critical("Error saving input to {}".format(test_file)) + if not passing: + LOGGER.info("Saved test case in file {}".format(test_file)) + else: + LOGGER.trace("Saved test case in file {}}".format(test_file)) + def report(self): """Report on the pass/fail status of a test case, and dump its log.""" info = self.context['info'] diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index ecd3b98..3807fd3 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -576,7 +576,7 @@ void makeFilename(char *name, size_t size) { } } -void writeInputData(char* name) { +void writeInputData(char* name, int important) { size_t path_len = 2 + sizeof(char) * (strlen(FLAGS_output_test_dir) + strlen(name)); char *path = (char *) malloc(path_len); snprintf(path, path_len, "%s/%s", FLAGS_output_test_dir, name); @@ -590,7 +590,11 @@ void writeInputData(char* name) { if (written != DeepState_InputSize) { DeepState_LogFormat(DeepState_LogError, "Failed to write to file `%s`", path); } else { - DeepState_LogFormat(DeepState_LogInfo, "Saved test case to file `%s`", path); + if (important) { + DeepState_LogFormat(DeepState_LogInfo, "Saved test case in file `%s`", path); + } else { + DeepState_LogFormat(DeepState_LogTrace, "Saved test case in file `%s`", path); + } } free(path); fclose(fp); @@ -602,7 +606,7 @@ void DeepState_SavePassingTest(void) { makeFilename(name, 40); name[40] = 0; strncat(name, ".pass", 48); - writeInputData(name); + writeInputData(name, 0); } /* Save a failing test to the output test directory. */ @@ -611,7 +615,7 @@ void DeepState_SaveFailingTest(void) { makeFilename(name, 40); name[40] = 0; strncat(name, ".fail", 48); - writeInputData(name); + writeInputData(name, 1); } /* Save a crashing test to the output test directory. */ @@ -620,7 +624,7 @@ void DeepState_SaveCrashingTest(void) { makeFilename(name, 40); name[40] = 0; strncat(name, ".crash", 48); - writeInputData(name); + writeInputData(name, 1); } /* Return the first test case to run. */ From dec77fd926f12ed9e489c7c771afb9b517676351 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 12:03:25 -0700 Subject: [PATCH 14/23] more quiet --- bin/deepstate/common.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index bdb3c5e..0004514 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -378,7 +378,7 @@ class DeepState(object): if not passing: LOGGER.info("Saved test case in file {}".format(test_file)) else: - LOGGER.trace("Saved test case in file {}}".format(test_file)) + LOGGER.trace("Saved test case in file {}".format(test_file)) def report(self): """Report on the pass/fail status of a test case, and dump its log.""" From 2b6e57b1e121e3fa97960cf5fd64086fa6726391 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 12:11:30 -0700 Subject: [PATCH 15/23] change FATAL to CRITICAL to match Python --- src/lib/Log.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lib/Log.c b/src/lib/Log.c index b352df1..78fe32f 100644 --- a/src/lib/Log.c +++ b/src/lib/Log.c @@ -58,7 +58,7 @@ static const char *DeepState_LogLevelStr(enum DeepState_LogLevel level) { case DeepState_LogExternal: return "EXTERNAL"; case DeepState_LogFatal: - return "FATAL"; + return "CRITICAL"; default: return "UNKNOWN"; } From 3133540027cec436ebfd30cea4928e6fda19d799 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 12:56:35 -0700 Subject: [PATCH 16/23] fix various messages in DeepState to be more helpful and consistent --- src/include/deepstate/DeepState.h | 11 +++++++---- src/lib/DeepState.c | 23 ++++++++++++++++++----- 2 files changed, 25 insertions(+), 9 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index 3364433..cbac2a2 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -705,8 +705,9 @@ static int DeepState_RunSingleSavedTestCase(void) { break; } } else { - DeepState_LogFormat(DeepState_LogInfo, - "No test specified, defaulting to first test"); + DeepState_LogFormat(DeepState_LogWarning, + "No test specified, defaulting to last test defined (%s)", + test->test_name); break; } } @@ -749,8 +750,10 @@ static int DeepState_RunSingleSavedTestDir(void) { break; } } else { - DeepState_LogFormat(DeepState_LogInfo, - "No test specified, defaulting to last test defined"); + DeepState_LogFormat(DeepState_LogWarning, + "No test specified, defaulting to last test defined (%s)", + test->test_name); + ; break; } } diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index 3807fd3..90740de 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -661,8 +661,8 @@ int DeepState_Fuzz(void){ long start = (long)time(NULL); long current = (long)time(NULL); - long diff = 0; - unsigned i = 0; + unsigned diff = 0; + unsigned int i = 0; int num_failed_tests = 0; @@ -676,8 +676,9 @@ int DeepState_Fuzz(void){ break; } } else { - DeepState_LogFormat(DeepState_LogInfo, - "No test specified, defaulting to last test defined"); + DeepState_LogFormat(DeepState_LogWarning, + "No test specified, defaulting to last test defined (%s)", + test->test_name); break; } } @@ -691,13 +692,25 @@ int DeepState_Fuzz(void){ while (diff < FLAGS_timeout) { i++; + if ((i > 1) && ((i & (i - 1)) == 0)) { + if (diff > 1) { + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u seconds. %d failed tests so far.", + i, diff, num_failed_tests); + } else if (diff == 1) { + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u second. %d failed tests so far.", + i, diff, num_failed_tests); + } else { + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in < 1 second. %d failed tests so far.", + i, diff, num_failed_tests); + } + } num_failed_tests += DeepState_FuzzOneTestCase(test); current = (long)time(NULL); diff = current-start; } - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests. %d failed tests.", + DeepState_LogFormat(DeepState_LogInfo, "Done fuzzing! Ran %u tests. %d failed tests.", i, num_failed_tests); return num_failed_tests; From 63952ff0679444012122fc7cf2b91201279d5d4d Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 12:58:42 -0700 Subject: [PATCH 17/23] fix output check in tests --- tests/test_crash.py | 2 +- tests/test_takeover.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_crash.py b/tests/test_crash.py index 5b53f83..f00b5e4 100644 --- a/tests/test_crash.py +++ b/tests/test_crash.py @@ -12,7 +12,7 @@ class CrashTest(deepstate_base.DeepStateTestCase): self.assertTrue("Passed: Crash_SegFault" in output) foundCrashSave = False for line in output.split("\n"): - if ("Saving input to" in line) and (".crash" in line): + if ("Saved test case" in line) and (".crash" in line): foundCrashSave = True self.assertTrue(foundCrashSave) diff --git a/tests/test_takeover.py b/tests/test_takeover.py index 94e39f0..e824f54 100644 --- a/tests/test_takeover.py +++ b/tests/test_takeover.py @@ -15,6 +15,6 @@ class TakeOverTest(deepstate_base.DeepStateTestCase): foundPassSave = False for line in output.split("\n"): - if ("Saving input to" in line) and (".pass" in line): + if ("Saved test case" in line) and (".pass" in line): foundPassSave = True self.assertTrue(foundPassSave) From 68307c11113d2a28238d60f4497c85c6be40e2f5 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 13:23:30 -0700 Subject: [PATCH 18/23] Much nicer fuzzer output with status updates --- src/lib/DeepState.c | 21 ++++++++------------- 1 file changed, 8 insertions(+), 13 deletions(-) diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index 90740de..0ef3291 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -689,20 +689,15 @@ int DeepState_Fuzz(void){ FLAGS_input_which_test); return 0; } + + unsigned int last_status = 0; while (diff < FLAGS_timeout) { i++; - if ((i > 1) && ((i & (i - 1)) == 0)) { - if (diff > 1) { - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u seconds. %d failed tests so far.", - i, diff, num_failed_tests); - } else if (diff == 1) { - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u second. %d failed tests so far.", - i, diff, num_failed_tests); - } else { - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in < 1 second. %d failed tests so far.", - i, diff, num_failed_tests); - } + if ((diff != last_status) && ((diff % 30) == 0) ) { + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u seconds (%u tests/second). %d failed tests so far.", + i, diff, i/diff, num_failed_tests); + last_status = diff; } num_failed_tests += DeepState_FuzzOneTestCase(test); @@ -710,8 +705,8 @@ int DeepState_Fuzz(void){ diff = current-start; } - DeepState_LogFormat(DeepState_LogInfo, "Done fuzzing! Ran %u tests. %d failed tests.", - i, num_failed_tests); + DeepState_LogFormat(DeepState_LogInfo, "Done fuzzing! Ran %u tests (%u tests/second). %d failed tests.", + i, i/diff, num_failed_tests); return num_failed_tests; } From 80e285a3bc13b14a1bfbbf278881520e62074f2c Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 14:29:55 -0700 Subject: [PATCH 19/23] Change fuzzing status to timestamped speed and failure count --- src/include/deepstate/DeepState.h | 4 ++-- src/include/deepstate/DeepState.hpp | 8 ++++---- src/lib/DeepState.c | 16 +++++++++------- 3 files changed, 15 insertions(+), 13 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index cbac2a2..af2ef28 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -773,7 +773,7 @@ static int DeepState_RunSingleSavedTestDir(void) { dir_fd = opendir(FLAGS_input_test_files_dir); if (dir_fd == NULL) { DeepState_LogFormat(DeepState_LogInfo, - "No tests to run."); + "No tests to run"); return 0; } @@ -825,7 +825,7 @@ static int DeepState_RunSavedTestCases(void) { /* Start DeepState and run the tests. Returns the number of failed tests. */ static int DeepState_Run(void) { if (!DeepState_OptionsAreInitialized) { - DeepState_Abandon("Please call DeepState_InitOptions(argc, argv) in main."); + DeepState_Abandon("Please call DeepState_InitOptions(argc, argv) in main"); } if (HAS_FLAG_input_test_dir) { diff --git a/src/include/deepstate/DeepState.hpp b/src/include/deepstate/DeepState.hpp index f895550..fc8ae98 100644 --- a/src/include/deepstate/DeepState.hpp +++ b/src/include/deepstate/DeepState.hpp @@ -301,7 +301,7 @@ static T Pump(T val, unsigned max=10) { return val; } if (!max) { - DeepState_Abandon("Must have a positive maximum number of values to pump."); + DeepState_Abandon("Must have a positive maximum number of values to Pump"); } for (auto i = 0U; i < max - 1; ++i) { T min_val = Minimize(val); @@ -341,7 +341,7 @@ inline static void OneOf(FuncTys&&... funcs) { inline static char OneOf(const char *str) { if (!str || !str[0]) { - DeepState_Abandon("NULL or empty string passed to OneOf."); + DeepState_Abandon("NULL or empty string passed to OneOf"); } return str[DeepState_IntInRange(0, strlen(str) - 1)]; } @@ -349,7 +349,7 @@ inline static char OneOf(const char *str) { template inline static const T &OneOf(const std::vector &arr) { if (arr.empty()) { - DeepState_Abandon("Empty vector passed to OneOf."); + DeepState_Abandon("Empty vector passed to OneOf"); } return arr[DeepState_IntInRange(0, arr.size() - 1)]; } @@ -358,7 +358,7 @@ inline static const T &OneOf(const std::vector &arr) { template inline static const T &OneOf(T (&arr)[len]) { if (!len) { - DeepState_Abandon("Empty array passed to OneOf."); + DeepState_Abandon("Empty array passed to OneOf"); } return arr[DeepState_IntInRange(0, len - 1)]; } diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index 0ef3291..81ca6c0 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -90,7 +90,7 @@ void DeepState_AllocCurrentTestRun(void) { mem_vis, 0, 0); if (shared_mem == MAP_FAILED) { - DeepState_Log(DeepState_LogError, "Unable to map shared memory."); + DeepState_Log(DeepState_LogError, "Unable to map shared memory"); exit(1); } @@ -173,11 +173,11 @@ void *DeepState_ConcretizeData(void *begin, void *end) { /* Return a symbolic C string of length `len`. */ char *DeepState_CStr(size_t len) { if (SIZE_MAX == len) { - DeepState_Abandon("Can't create an SIZE_MAX-length string."); + DeepState_Abandon("Can't create an SIZE_MAX-length string"); } char *str = (char *) malloc(sizeof(char) * (len + 1)); if (NULL == str) { - DeepState_Abandon("Can't allocate memory."); + DeepState_Abandon("Can't allocate memory"); } if (len) { DeepState_SymbolizeData(str, &(str[len - 1])); @@ -695,8 +695,10 @@ int DeepState_Fuzz(void){ while (diff < FLAGS_timeout) { i++; if ((diff != last_status) && ((diff % 30) == 0) ) { - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests in %u seconds (%u tests/second). %d failed tests so far.", - i, diff, i/diff, num_failed_tests); + time_t t = time(NULL); + struct tm tm = *localtime(&t); + DeepState_LogFormat(DeepState_LogInfo, "%d-%02d-%02d %02d:%02d:%02d: %u tests/second / %d failed tests so far", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, i/diff, num_failed_tests); last_status = diff; } num_failed_tests += DeepState_FuzzOneTestCase(test); @@ -705,7 +707,7 @@ int DeepState_Fuzz(void){ diff = current-start; } - DeepState_LogFormat(DeepState_LogInfo, "Done fuzzing! Ran %u tests (%u tests/second). %d failed tests.", + DeepState_LogFormat(DeepState_LogInfo, "Done fuzzing! Ran %u tests (%u tests/second) with %d failed tests", i, i/diff, num_failed_tests); return num_failed_tests; @@ -804,7 +806,7 @@ void __assert_fail(const char * assertion, const char * file, } void __stack_chk_fail(void) { - DeepState_Log(DeepState_LogFatal, "Stack smash detected."); + DeepState_Log(DeepState_LogFatal, "Stack smash detected"); __builtin_unreachable(); } From ca400bc2a0777ba60996df9e479d9d48bf9cff8d Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 14:52:46 -0700 Subject: [PATCH 20/23] fix so count of failed tests is correct --- src/include/deepstate/DeepState.h | 5 +++-- src/lib/DeepState.c | 4 +++- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index af2ef28..c6d5d83 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -860,8 +860,9 @@ static int DeepState_Run(void) { } else { DeepState_Begin(test); } - - num_failed_tests += DeepState_ForkAndRunTest(test); + if (DeepState_ForkAndRunTest(test) != 0) { + num_failed_tests++; + } } if (use_drfuzz) { diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index 81ca6c0..48c0c3d 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -701,7 +701,9 @@ int DeepState_Fuzz(void){ tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, i/diff, num_failed_tests); last_status = diff; } - num_failed_tests += DeepState_FuzzOneTestCase(test); + if (DeepState_FuzzOneTestCase(test) != 0) { + num_failed_tests ++; + } current = (long)time(NULL); diff = current-start; From 91b8b5b8d149a19e17e450531db158361394c472 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 15:02:59 -0700 Subject: [PATCH 21/23] Fix the mac OS abort problem with libFuzzer --- src/include/deepstate/DeepState.h | 4 ++-- src/lib/DeepState.c | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index c6d5d83..227cb17 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -724,7 +724,7 @@ static int DeepState_RunSingleSavedTestCase(void) { if ((result == DeepState_TestRunFail) || (result == DeepState_TestRunCrash)) { if (FLAGS_abort_on_fail) { - abort(); + assert(0); // Terminate in a way AFL/etc. can see as a crash } num_failed_tests++; } @@ -790,7 +790,7 @@ static int DeepState_RunSingleSavedTestDir(void) { if ((result == DeepState_TestRunFail) || (result == DeepState_TestRunCrash)) { if (FLAGS_abort_on_fail) { - abort(); + assert(0); // Terminate in a way AFL/etc. can see as a crash } num_failed_tests++; diff --git a/src/lib/DeepState.c b/src/lib/DeepState.c index 48c0c3d..a62395a 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -741,7 +741,7 @@ enum DeepState_TestRunResult DeepState_FuzzOneTestCase(struct DeepState_TestInfo if (FLAGS_abort_on_fail && ((result == DeepState_TestRunCrash) || (result == DeepState_TestRunFail))) { - abort(); + assert(0); // Terminate the testing in a way AFL/etc. can see as a crash } return result; @@ -783,7 +783,7 @@ extern int LLVMFuzzerTestOneInput(const uint8_t *Data, size_t Size) { const char* abort_check = getenv("LIBFUZZER_ABORT_ON_FAIL"); if (abort_check != NULL) { if ((result == DeepState_TestRunFail) || (result == DeepState_TestRunCrash)) { - abort(); + assert(0); // Terminate the testing more permanently } } From d2b632ef25291edc98edf5cdd867c8782efb2c98 Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 15:28:26 -0700 Subject: [PATCH 22/23] default replay of multiple tests to a quiet mode --- src/include/deepstate/DeepState.h | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index 227cb17..436f9a2 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -742,6 +742,10 @@ static int DeepState_RunSingleSavedTestDir(void) { int num_failed_tests = 0; struct DeepState_TestInfo *test = NULL; + if (!HAS_FLAG_log_level) { + FLAGS_log_level = 2; + } + DeepState_Setup(); for (test = DeepState_FirstTest(); test != NULL; test = test->prev) { @@ -811,6 +815,10 @@ static int DeepState_RunSavedTestCases(void) { int num_failed_tests = 0; struct DeepState_TestInfo *test = NULL; + if (!HAS_FLAG_log_level) { + FLAGS_log_level = 2; + } + DeepState_Setup(); for (test = DeepState_FirstTest(); test != NULL; test = test->prev) { @@ -828,14 +836,14 @@ static int DeepState_Run(void) { DeepState_Abandon("Please call DeepState_InitOptions(argc, argv) in main"); } - if (HAS_FLAG_input_test_dir) { - return DeepState_RunSavedTestCases(); - } - if (HAS_FLAG_input_test_file) { return DeepState_RunSingleSavedTestCase(); } + if (HAS_FLAG_input_test_dir) { + return DeepState_RunSavedTestCases(); + } + if (HAS_FLAG_input_test_files_dir) { return DeepState_RunSingleSavedTestDir(); } From fadd43ce7165635341633183d60ec6c3c9fefb3f Mon Sep 17 00:00:00 2001 From: Alex Groce Date: Thu, 3 Jan 2019 15:48:11 -0700 Subject: [PATCH 23/23] test replay is quiet but reports numbers --- src/include/deepstate/DeepState.h | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index 436f9a2..1f06847 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -674,9 +674,12 @@ static int DeepState_RunSavedCasesForTest(struct DeepState_TestInfo *test) { return 0; } + unsigned int i = 0; + /* Read generated test cases and run a test for each file found. */ while ((dp = readdir(dir_fd)) != NULL) { if (DeepState_IsTestCaseFile(dp->d_name)) { + i++; enum DeepState_TestRunResult result = DeepState_RunSavedTestCase(test, test_case_dir, dp->d_name); @@ -688,6 +691,9 @@ static int DeepState_RunSavedCasesForTest(struct DeepState_TestInfo *test) { closedir(dir_fd); free(test_case_dir); + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests; %d tests failed", + i, num_failed_tests); + return num_failed_tests; } @@ -781,6 +787,8 @@ static int DeepState_RunSingleSavedTestDir(void) { return 0; } + unsigned int i = 0; + /* Read generated test cases and run a test for each file found. */ while ((dp = readdir(dir_fd)) != NULL) { size_t path_len = 2 + sizeof(char) * (strlen(FLAGS_input_test_files_dir) + strlen(dp->d_name)); @@ -789,6 +797,7 @@ static int DeepState_RunSingleSavedTestDir(void) { stat(path, &path_stat); if (S_ISREG(path_stat.st_mode)) { + i++; enum DeepState_TestRunResult result = DeepState_RunSavedTestCase(test, FLAGS_input_test_files_dir, dp->d_name); @@ -803,6 +812,9 @@ static int DeepState_RunSingleSavedTestDir(void) { } closedir(dir_fd); + DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests; %d tests failed", + i, num_failed_tests); + return num_failed_tests; }