DeforaNetworks/deepstate
3
0
Fork 0
Code Releases Activity

Merge pull request #157 from trailofbits/more_readable_output

Browse Source 
Change symex and fuzzing outputs to default to something readable and friendly
This commit is contained in:
Alex Groce
2019-01-03 17:24:47 -07:00
committed by GitHub
parent 1247ac64a2 fadd43ce71
commit 405a1948d7
8 changed files with 118 additions and 49 deletions
Download Patch File Download Diff File Expand all files Collapse all files
bin/deepstate/common.py
+30 -6
View File
@@ -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):
src/include/deepstate/DeepState.h
+39 -15
View File
@@ -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) {
src/include/deepstate/DeepState.hpp
+6 -6
View File
@@ -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 <typename T>
inline static const T &OneOf(const std::vector<T> &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<T> &arr) {
template <typename T, int len>
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, !=)
src/lib/DeepState.c
+38 -18
View File
@@ -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();
}
src/lib/Log.c
+1 -1
View File
@@ -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";
}
tests/logrun.py
+2 -1
View File
@@ -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()
tests/test_crash.py
+1 -1
View File
@@ -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)
tests/test_takeover.py
+1 -1
View File
@@ -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)