Improve logging and statistics

Close #33

cobrafuzz/fuzzer.py

@@ -15,7 +15,6 @@
 
 from cobrafuzz import state as st, tracer
 
-logging.getLogger().addHandler(logging.StreamHandler(sys.stdout))
 logging.getLogger().setLevel(logging.DEBUG)
 
 MPContext = Union[mp.context.ForkContext, mp.context.ForkServerContext, mp.context.SpawnContext]
@@ -112,7 +111,7 @@ def worker_loop(  # noqa: PLR0913
     state: st.State,
 ) -> None:
     class NullFile(io.StringIO):
-        """No-op to trash stdout away."""
+        """IO implementation that discards all writes."""
 
         def write(self, arg: str) -> int:
             return len(arg)
@@ -151,9 +150,9 @@ def write(self, arg: str) -> int:
         if type(result) == Status and time.time() - last_status <= stat_frequency:
             continue
 
-        runs = 0
         last_status = time.time()
         result_queue.put(result)
+        runs = 0
 
 
 def _worker_run(
@@ -243,8 +242,9 @@ def __init__(  # noqa: PLR0913
 
         self._current_crashes = 0
         self._current_runs = 0
-        self._last_runs = 0
+        self._start_time = time.time()
         self._last_stats_time = time.time()
+        self._last_crash: Optional[float] = None
 
         self._mp_ctx: MPContext = (
             mp.get_context("fork")
@@ -318,21 +318,24 @@ def _load_crashes(self, regression: bool) -> None:
 
     def _log_stats(self, log_type: str, total_coverage: int, corpus_size: int) -> None:
         end_time = time.time()
-        execs_per_second = int(
-            (self._current_runs - self._last_runs) / (end_time - self._last_stats_time),
-        )
+        execs_per_second = self._current_runs // (end_time - self._start_time)
 
         self._last_stats_time = end_time
         self._last_runs = self._current_runs
 
         logging.info(
-            "#%d %s     cov: %d corp: %d exec/s: %d crashes: %d",
+            "#%9.9d %s cov: %d, corp: %d, exec/s: %d, crashes: %d%s",
             self._current_runs,
             log_type,
             total_coverage,
             corpus_size,
             execs_per_second,
             self._current_crashes,
+            (
+                f", last: {int(end_time - self._last_crash) // 60} mins ago"
+                if self._last_crash
+                else ""
+            ),
         )
 
     def _write_sample(self, buf: bytes, prefix: str = "crash-") -> None:
@@ -382,7 +385,7 @@ def start(self) -> None:  # noqa: PLR0912
         self._workers = [self._initialize_process(wid=wid) for wid in range(self._num_workers)]
 
         logging.info(
-            "#0 READ units: %d workers: %d seeds: %d",
+            "START units: %d, workers: %d, seeds: %d",
             self._state.size,
             self._num_workers,
             self._state.num_seeds,
@@ -431,12 +434,13 @@ def start(self) -> None:  # noqa: PLR0912
                     if improvement:
                         logging.info(result.message)
                         self._current_crashes += 1
+                        self._last_crash = time.time()
                         self._write_sample(result.data)
 
                 elif isinstance(result, Report):
                     improvement = self._state.store_coverage(result.covered)
                     if improvement:
-                        self._log_stats("NEW", self._state.total_coverage, self._state.size)
+                        self._log_stats("  NEW", self._state.total_coverage, self._state.size)
                         self._state.put_input(bytearray(result.data))
                         self._state.save()
 

cobrafuzz/main.py

@@ -1,4 +1,5 @@
 import argparse
+import logging
 import sys
 from pathlib import Path
 from typing import Callable
@@ -98,6 +99,7 @@ def __call__(self) -> None:
             start_method=args.start_method,
             state_file=args.state_file,
         )
+        logging.basicConfig(format="[%(asctime)s] %(message)s")
         try:
             f.start()
         except KeyboardInterrupt:

tests/unit/test_fuzzer.py

@@ -134,7 +134,7 @@ def test_stats(
             f.start()
         f._log_stats("CUSTOM", total_coverage=123, corpus_size=5)  # noqa: SLF001
     assert re.match(
-        r".*CUSTOM\s+cov: 123 corp: 5 exec/s: \d+ crashes: 0\n.*",
+        r".*CUSTOM\s+cov: 123, corp: 5, exec/s: \d+, crashes: 0\n.*",
         caplog.text,
         flags=re.DOTALL,
     )
@@ -376,7 +376,7 @@ def test_timeout(
         with pytest.raises(SystemExit, match="^0$"), caplog.at_level(logging.INFO):
             f.start()
     assert caplog.record_tuples == [
-        ("root", logging.INFO, "#0 READ units: 1 workers: 1 seeds: 0"),
+        ("root", logging.INFO, "START units: 1, workers: 1, seeds: 0"),
         ("root", logging.INFO, "Timeout after 10 seconds, stopping."),
     ]
 
@@ -402,7 +402,7 @@ def test_start_no_progress(
         p.setattr(f, "_result_queue", result_queue)
         with pytest.raises(SystemExit, match="^0$"), caplog.at_level(logging.INFO):
             f.start()
-    assert caplog.record_tuples[0] == ("root", logging.INFO, "#0 READ units: 1 workers: 1 seeds: 0")
+    assert caplog.record_tuples[0] == ("root", logging.INFO, "START units: 1, workers: 1, seeds: 0")
     assert caplog.record_tuples[-1] == ("root", logging.INFO, "Performed 1 runs (0/s), stopping.")
 
 
@@ -429,7 +429,7 @@ def test_start_status(
         with pytest.raises(SystemExit, match="^0$"), caplog.at_level(logging.INFO):
             f.start()
     assert caplog.record_tuples == [
-        ("root", logging.INFO, "#0 READ units: 1 workers: 2 seeds: 0"),
+        ("root", logging.INFO, "START units: 1, workers: 2, seeds: 0"),
         ("root", logging.INFO, "Performed 1 runs (0/s), stopping."),
     ]
 
@@ -467,8 +467,8 @@ def test_start_progress_with_update(
         assert update.covered == covered
 
     assert caplog.record_tuples == [
-        ("root", logging.INFO, "#0 READ units: 1 workers: 2 seeds: 0"),
-        ("root", logging.INFO, "#1 NEW     cov: 0 corp: 1 exec/s: 0 crashes: 0"),
+        ("root", logging.INFO, "START units: 1, workers: 2, seeds: 0"),
+        ("root", logging.INFO, "#000000001   NEW cov: 0, corp: 1, exec/s: 0, crashes: 0"),
         ("root", logging.INFO, "Performed 1 runs (0/s), stopping."),
     ]
 
@@ -505,8 +505,8 @@ def test_start_pulse(
         with pytest.raises(SystemExit, match="^0$"), caplog.at_level(logging.INFO):
             f.start()
     assert caplog.record_tuples == [
-        ("root", logging.INFO, "#0 READ units: 1 workers: 1 seeds: 0"),
-        ("root", logging.INFO, "#2 PULSE     cov: 0 corp: 1 exec/s: 0 crashes: 0"),
+        ("root", logging.INFO, "START units: 1, workers: 1, seeds: 0"),
+        ("root", logging.INFO, "#000000002 PULSE cov: 0, corp: 1, exec/s: 0, crashes: 0"),
         ("root", logging.INFO, "Timeout after 10 seconds, stopping."),
     ]
 
@@ -544,7 +544,7 @@ def test_start_error(
             f.start()
     filename = f"crash-{digest}"
     assert caplog.record_tuples == [
-        ("root", logging.INFO, "#0 READ units: 1 workers: 1 seeds: 0"),
+        ("root", logging.INFO, "START units: 1, workers: 1, seeds: 0"),
         ("root", logging.INFO, "Test error message"),
         ("root", logging.INFO, f"sample was written to {tmp_path / filename}"),
         ("root", logging.INFO, "sample = 6465616462656566"),