diff --git a/bin/deepstate/common.py b/bin/deepstate/common.py index 1ee596b..0004514 100644 --- a/bin/deepstate/common.py +++ b/bin/deepstate/common.py @@ -45,9 +45,12 @@ LOG_LEVEL_FATAL = 6 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, - 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, @@ -137,8 +140,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 +247,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'] @@ -256,6 +263,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), @@ -341,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'] @@ -385,7 +409,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 +518,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): diff --git a/src/include/deepstate/DeepState.h b/src/include/deepstate/DeepState.h index 183d323..2912763 100644 --- a/src/include/deepstate/DeepState.h +++ b/src/include/deepstate/DeepState.h @@ -489,7 +489,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); } @@ -677,9 +677,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); @@ -691,6 +694,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; } @@ -708,8 +714,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; } } @@ -726,7 +733,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++; } @@ -744,6 +751,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) { @@ -752,8 +763,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; } } @@ -773,10 +786,12 @@ 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; } + 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)); @@ -785,12 +800,13 @@ 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); 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++; @@ -799,6 +815,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; } @@ -811,6 +830,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) { @@ -825,17 +848,17 @@ 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."); - } - - if (HAS_FLAG_input_test_dir) { - return DeepState_RunSavedTestCases(); + DeepState_Abandon("Please call DeepState_InitOptions(argc, argv) in main"); } 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(); } @@ -860,8 +883,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/include/deepstate/DeepState.hpp b/src/include/deepstate/DeepState.hpp index e4c0617..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)]; } @@ -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/src/lib/DeepState.c b/src/lib/DeepState.c index 411583a..dd2c84e 100644 --- a/src/lib/DeepState.c +++ b/src/lib/DeepState.c @@ -92,7 +92,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); } @@ -175,11 +175,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])); @@ -582,7 +582,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); @@ -596,7 +596,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); @@ -608,7 +612,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. */ @@ -617,7 +621,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. */ @@ -626,7 +630,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. */ @@ -648,6 +652,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); @@ -659,8 +667,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; @@ -674,8 +682,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; } } @@ -686,17 +695,28 @@ int DeepState_Fuzz(void){ FLAGS_input_which_test); return 0; } + + unsigned int last_status = 0; while (diff < FLAGS_timeout) { i++; - num_failed_tests += DeepState_FuzzOneTestCase(test); + if ((diff != last_status) && ((diff % 30) == 0) ) { + 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; + } + if (DeepState_FuzzOneTestCase(test) != 0) { + num_failed_tests ++; + } current = (long)time(NULL); diff = current-start; } - DeepState_LogFormat(DeepState_LogInfo, "Ran %u tests. %d failed tests.", - i, num_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; } @@ -727,7 +747,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; @@ -769,7 +789,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 } } @@ -794,7 +814,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(); } 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"; } diff --git a/tests/logrun.py b/tests/logrun.py index 3c9c5c4..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, 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() 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)