From 1d83c2daf4947fc59bd84a2cafaa169bb311e631 Mon Sep 17 00:00:00 2001 From: Henrik Brodin <90325907+hbrodin@users.noreply.github.com> Date: Wed, 21 Jan 2026 13:03:00 +0100 Subject: [PATCH] Improve fuzzer logging (#416) To help when integrating new harnesses with buttercup, this provides more detailed logging about harness execution and exit. --- .../buttercup/fuzzing_infra/runner_proxy.py | 61 +++++++++++++++++-- fuzzer/tests/test_runner_proxy.py | 2 +- .../src/buttercup/fuzzer_runner/runner.py | 24 ++++++++ 3 files changed, 82 insertions(+), 5 deletions(-) diff --git a/fuzzer/src/buttercup/fuzzing_infra/runner_proxy.py b/fuzzer/src/buttercup/fuzzing_infra/runner_proxy.py index 745a4406..129a169f 100644 --- a/fuzzer/src/buttercup/fuzzing_infra/runner_proxy.py +++ b/fuzzer/src/buttercup/fuzzing_infra/runner_proxy.py @@ -91,13 +91,38 @@ class RunnerProxy: try: stdout, stderr = process.communicate(timeout=subprocess_timeout) - if process.returncode != 0: + + # Log the return code with interpretation + returncode = process.returncode + if returncode != 0: + # Interpret common exit codes + if returncode > 128: + signal_num = returncode - 128 + try: + signal_name = signal.Signals(signal_num).name + except ValueError: + signal_name = f"signal {signal_num}" + logger.warning( + f"{task_type} process terminated by {signal_name} " + f"(exit code {returncode} = 128 + {signal_num})" + ) + elif returncode == 1: + logger.warning(f"{task_type} process exited with code 1 (general error)") + elif returncode == 77: + logger.warning(f"{task_type} process exited with code 77 (libFuzzer: no corpus)") + elif returncode == 124: + logger.warning(f"{task_type} process exited with code 124 (timeout)") + else: + logger.warning(f"{task_type} process exited with code {returncode}") + error_msg = stderr.decode("utf-8") if stderr else "Unknown subprocess error" logger.error(f"{task_type} task failed: {error_msg}") return { "status": "failed", - "error": f"Task failed: {error_msg}", + "error": f"Task failed (exit code {returncode}): {error_msg}", } + else: + logger.debug(f"{task_type} process exited successfully (code 0)") except subprocess.TimeoutExpired: logger.error(f"{task_type} task timed out after {subprocess_timeout} seconds") if process.poll() is None: @@ -197,6 +222,34 @@ class RunnerProxy: """Convert dictionary result back to FuzzResult object""" # Handle both "logs" and "error" keys for backward compatibility logs = result_dict.get("logs", result_dict.get("error", "")) + stats = result_dict.get("stats", {}) + crashes = result_dict.get("crashes", []) + + # Log detailed stats for debugging harness issues + logger.info( + f"Fuzzer result: num_crashes={len(crashes)}, " + f"timed_out={result_dict.get('timed_out', False)}, " + f"time_executed={result_dict.get('time_executed', 0.0):.2f}s" + ) + if stats: + oom_count = stats.get("oom_count", 0) + timeout_count = stats.get("timeout_count", 0) + crash_count = stats.get("crash_count", 0) + startup_crash_count = stats.get("startup_crash_count", 0) + + if oom_count > 0: + logger.warning(f"Fuzzer detected OOM: oom_count={oom_count}") + if timeout_count > 0: + logger.warning(f"Fuzzer detected timeouts: timeout_count={timeout_count}") + if startup_crash_count > 0: + logger.warning(f"Fuzzer detected startup crashes: startup_crash_count={startup_crash_count}") + + logger.info( + f"Fuzzer stats summary: crash_count={crash_count}, oom_count={oom_count}, " + f"timeout_count={timeout_count}, startup_crash_count={startup_crash_count}, " + f"edge_coverage={stats.get('edge_coverage', 0)}/{stats.get('edges_total', 0)}" + ) + return FuzzResult( logs=logs, crashes=[ @@ -206,9 +259,9 @@ class RunnerProxy: reproduce_args=crash.get("reproduce_args", []), crash_time=crash.get("crash_time", 0.0), ) - for crash in result_dict.get("crashes", []) + for crash in crashes ], - stats=result_dict.get("stats", {}), + stats=stats, time_executed=result_dict.get("time_executed", 0.0), timed_out=result_dict.get("timed_out", False), command=result_dict.get("command", ""), diff --git a/fuzzer/tests/test_runner_proxy.py b/fuzzer/tests/test_runner_proxy.py index cafdcdc9..bbdb1e7f 100644 --- a/fuzzer/tests/test_runner_proxy.py +++ b/fuzzer/tests/test_runner_proxy.py @@ -107,7 +107,7 @@ def test_run_fuzzer_failure(mock_popen, fuzz_config): # Run fuzzer and expect failure res = runner_proxy.run_fuzzer(fuzz_config) - assert "Task failed: Fuzzer crashed" in res.logs + assert "Task failed (exit code 1): Fuzzer crashed" in res.logs assert res.crashes == [] assert res.command == "" diff --git a/fuzzer_runner/src/buttercup/fuzzer_runner/runner.py b/fuzzer_runner/src/buttercup/fuzzer_runner/runner.py index 70c083bd..840fce9e 100644 --- a/fuzzer_runner/src/buttercup/fuzzer_runner/runner.py +++ b/fuzzer_runner/src/buttercup/fuzzer_runner/runner.py @@ -71,6 +71,30 @@ class Runner: def run_fuzzer_command(args: argparse.Namespace, runner: Runner, fuzzconf: FuzzConfiguration) -> dict[str, typing.Any]: """Run fuzzer command""" result = runner.run_fuzzer(fuzzconf) + + # Log detailed fuzzer result information + stats = result.stats or {} + logger.info( + f"Fuzzer completed: crashes={len(result.crashes)}, " + f"timed_out={result.timed_out}, time_executed={result.time_executed:.2f}s" + ) + logger.info( + f"Fuzzer stats: crash_count={stats.get('crash_count', 0)}, " + f"oom_count={stats.get('oom_count', 0)}, " + f"timeout_count={stats.get('timeout_count', 0)}, " + f"startup_crash_count={stats.get('startup_crash_count', 0)}, " + f"leak_count={stats.get('leak_count', 0)}" + ) + logger.info( + f"Fuzzer coverage: edge_coverage={stats.get('edge_coverage', 0)}/{stats.get('edges_total', 0)}, " + f"feature_coverage={stats.get('feature_coverage', 0)}, " + f"new_edges={stats.get('new_edges', 0)}, new_features={stats.get('new_features', 0)}" + ) + + if result.crashes: + for i, crash in enumerate(result.crashes): + logger.info(f"Crash {i + 1}: input_path={crash.input_path}, crash_time={crash.crash_time}") + result_dict = { "logs": result.logs, "command": result.command,