AFL Internals - Stats, Counters and the UI

Introduction

In a previous article, AFL stages are explained in detail. This time, I’ll try to go over the elements that make up the user interface. There are plenty of stats generated by a fuzzing session. For instance, you can track the overall progress by counters such as cycles done, total paths, unique crashes and unique hangs. Join to learn more.

The User Interface

The User Interface

The above is similar to what one might observe when AFL is run. The user interface is divided into 8 sections. There is also a CPU meter at the bottom of the screen to the right. Let’s start by describing the particulars.

Calibration

Before delving into the metrics, let’s look into the calibration stage that is called in various places. Calibration stage basically collects important information about the current queue item and the target.

/* Calibrate a new test case. This is done when processing the input directory
   to warn about flaky or otherwise problematic test cases early on; and when
   new paths are discovered to detect variable behavior and so on. */
static u8 calibrate_case(char** argv, struct queue_entry* q, u8* use_mem,
                         u32 handicap, u8 from_queue) {
  static u8 first_trace[MAP_SIZE];
  u8  fault = 0, new_bits = 0, var_detected = 0, hnb = 0,
      first_run = (q->exec_cksum == 0);
  u64 start_us, stop_us;
  s32 old_sc = stage_cur, old_sm = stage_max;
  u32 use_tmout = exec_tmout;
  u8* old_sn = stage_name;
  /* Be a bit more generous about timeouts when resuming sessions, or when
     trying to calibrate already-added finds. This helps avoid trouble due
     to intermittent latency. */
  if (!from_queue || resuming_fuzz)
    use_tmout = MAX(exec_tmout + CAL_TMOUT_ADD,
                exec_tmout * CAL_TMOUT_PERC / 100);

First, calibration picks a longer timeout value. CAL_TMOUT_ADD is defined to be 50ms and CAL_TMOUT_PERC is defined to be 125 in config.h.

  q->cal_failed++;

  stage_name = "calibration";
  stage_max  = fast_cal ? 3 : CAL_CYCLES;

The number of calibration cycles is CAL_CYCLES by default. In config.h, it is defined to be 8.

  /* Make sure the forkserver is up before we do anything, and let's not
     count its spin-up time toward binary calibration. */
  if (dumb_mode != 1 && !no_forkserver && !forksrv_pid)
    init_forkserver(argv);

Let’s run the forkserver.

  if (q->exec_cksum) {
    memcpy(first_trace, trace_bits, MAP_SIZE);
    hnb = has_new_bits(virgin_bits);
    if (hnb > new_bits) new_bits = hnb;
  }

Detect if the queue item has already been fuzzed. Copy the trace_bits into first_trace. MAP_SIZE is still 64KiB.

  start_us = get_cur_time_us();

Mark the moment and proceed into the rounds.

  for (stage_cur = 0; stage_cur < stage_max; stage_cur++) {
    u32 cksum;
    if (!first_run && !(stage_cur % stats_update_freq)) show_stats();
    write_to_testcase(use_mem, q->len);
    fault = run_target(argv, use_tmout);
    /* stop_soon is set by the handler for Ctrl+C. When it's pressed,
       we want to bail out quickly. */
    if (stop_soon || fault != crash_mode) goto abort_calibration;
    if (!dumb_mode && !stage_cur && !count_bytes(trace_bits)) {
      fault = FAULT_NOINST;
      goto abort_calibration;
    }

The above code runs the target and checks for failures, nothing interesting so far.

    cksum = hash32(trace_bits, MAP_SIZE, HASH_CONST);
    if (q->exec_cksum != cksum) {

Calculate the checksum and see if we get any new edges.

      hnb = has_new_bits(virgin_bits);
      if (hnb > new_bits) new_bits = hnb;

Merge new bits into virgin_bits. Virgins bits is the map that holds untouched bits so far. Let’s see the definition of has_new_bits():

static inline u8 has_new_bits(u8* virgin_map) {
#ifdef WORD_SIZE_64
 .. skipd for brevity ..
#else
  u32* current = (u32*)trace_bits;
  u32* virgin  = (u32*)virgin_map;
  u32  i = (MAP_SIZE >> 2);
#endif /* ^WORD_SIZE_64 */

  u8   ret = 0;
  while (i--) {
  if (unlikely(*current) && unlikely(*current & *virgin)) {
    if (likely(ret < 2)) {
      u8* cur = (u8*)current;
      u8* vir = (u8*)virgin;
#ifdef WORD_SIZE_64
 .. skipd for brevity ..
#else
        if ((cur[0] && vir[0] == 0xff) || (cur[1] && vir[1] == 0xff) ||
            (cur[2] && vir[2] == 0xff) || (cur[3] && vir[3] == 0xff)) ret = 2;
        else ret = 1;
#endif /* ^WORD_SIZE_64 */
      }
      *virgin &= ~*current;
    }
    current++;
    virgin++;
  }
  if (ret && virgin_map == virgin_bits) bitmap_changed = 1;
  return ret;
}

Note that, virgin_bits is set to all ones at the beginning and *virgin &= ~*current clears the relevant bits. This function returns 1 if only hitcounts are changed, 2 if we see new edges, 0 otherwise. Let’s continue with calibration.

      if (q->exec_cksum) {
        u32 i;
        for (i = 0; i < MAP_SIZE; i++) {
          if (!var_bytes[i] && first_trace[i] != trace_bits[i]) {
            var_bytes[i] = 1;
            stage_max    = CAL_CYCLES_LONG;
          }
        }
        var_detected = 1;

If it is the first run, mark in var_bytes[] and increase the number of stages to CAL_CYCLES_LONG which is defined to be 40 in config.h.

      } else {
        q->exec_cksum = cksum;
        memcpy(first_trace, trace_bits, MAP_SIZE);
      }
    }
  }

Else, update first_trace and checksum.

  stop_us = get_cur_time_us();
  total_cal_us     += stop_us - start_us;
  total_cal_cycles += stage_max;

Mark the moment, calculate the calibration time in microseconds, and save number of calibration cycles.

  q->exec_us     = (stop_us - start_us) / stage_max;
  q->bitmap_size = count_bytes(trace_bits);
  q->handicap    = handicap;
  q->cal_failed  = 0;

Save metrics into the queue item. count_bytes() basically counts the number of bytes different from zero in trace_bits.

  total_bitmap_size += q->bitmap_size;
  total_bitmap_entries++;

  update_bitmap_score(q);

Save the total bitmap size and increase the number of entries. Let’s look into the update_bitmap_score(). The purpose of this function is basically favor some of the items in the queue according to a metric. That particular metric is called fav_factor and calculated by execution time multiplied by the input length.

static struct queue_entry*
  top_rated[MAP_SIZE];                /* Top entries for bitmap bytes     */

A global variable top_rated[] holds the favorable items. It will be used in cull_queue() to pick favorable items in the main fuzzer loop.

/* When we bump into a new path, we call this to see if the path appears
   more "favorable" than any of the existing ones. The purpose of the
   "favorables" is to have a minimal set of paths that trigger all the bits
   seen in the bitmap so far, and focus on fuzzing them at the expense of
   the rest.

   The first step of the process is to maintain a list of top_rated[] entries
   for every byte in the bitmap. We win that slot if there is no previous
   contender, or if the contender has a more favorable speed x size factor. */
static void update_bitmap_score(struct queue_entry* q) {
  u32 i;
  u64 fav_factor = q->exec_us * q->len;

Calculate the metric.

  /* For every byte set in trace_bits[], see if there is a previous winner,
     and how it compares to us. */
  for (i = 0; i < MAP_SIZE; i++)
    if (trace_bits[i]) {
       if (top_rated[i]) {
         /* Faster-executing or smaller test cases are favored. */
         if (fav_factor > top_rated[i]->exec_us * top_rated[i]->len) continue;

Skip if what we have is better.

         /* Looks like we're going to win. Decrease ref count for the
            previous winner, discard its trace_bits[] if necessary. */
         if (!--top_rated[i]->tc_ref) {
           ck_free(top_rated[i]->trace_mini);
           top_rated[i]->trace_mini = 0;
         }
       }

Release the current one since we have a better one.

       /* Insert ourselves as the new winner. */
       top_rated[i] = q;
       q->tc_ref++;

       if (!q->trace_mini) {
         q->trace_mini = ck_alloc(MAP_SIZE >> 3);
         minimize_bits(q->trace_mini, trace_bits);
       }
       score_changed = 1;
     }
}

Save the new one in top_rated[], increase the reference count, save trace_bits in the item and minimize. Minimization basically drops counts.

  /* If this case didn't result in new output from the instrumentation, tell
     parent. This is a non-critical problem, but something to warn the user
     about. */

  if (!dumb_mode && first_run && !fault && !new_bits) fault = FAULT_NOBITS;
abort_calibration:
  if (new_bits == 2 && !q->has_new_cov) {
    q->has_new_cov = 1;
    queued_with_cov++;
  }

Inform that we have a new edge.

  /* Mark variable paths. */
  if (var_detected) {
    var_byte_count = count_bytes(var_bytes);
    if (!q->var_behavior) {
      mark_as_variable(q);
      queued_variable++;
    }
  }

If first run and variable bytes detected, mark the item as variable. mark_as_variable() basically creates a file named in output/queue/.state/variable_behavior/ so that next time the fuzzer loads, the information is preserved.

  stage_name = old_sn;
  stage_cur  = old_sc;
  stage_max  = old_sm;

  if (!first_run) show_stats();
  return fault;
}

Restore globals and if not the first run, show counters.

Decision Making and cull_queue()

Let’s revisit cull_queue() to see how top_rated[] items are favored.

/* The second part of the mechanism discussed above is a routine that
   goes over top_rated[] entries, and then sequentially grabs winners for
   previously-unseen bytes (temp_v) and marks them as favored, at least
   until the next run. The favored entries are given more air time during
   all fuzzing steps. */
static void cull_queue(void) {
  struct queue_entry* q;
  static u8 temp_v[MAP_SIZE >> 3];
  u32 i;

  if (dumb_mode || !score_changed) return;

  score_changed = 0;
  memset(temp_v, 255, MAP_SIZE >> 3);
  queued_favored  = 0;
  pending_favored = 0;
  q = queue;
  while (q) {
    q->favored = 0;
    q = q->next;
  }

Set temp_v to all ones, reset all locals, reset all favorites.


  /* Let's see if anything in the bitmap isn't captured in temp_v.
     If yes, and if it has a top_rated[] contender, let's use it. */
  for (i = 0; i < MAP_SIZE; i++)
    if (top_rated[i] && (temp_v[i >> 3] & (1 << (i & 7)))) {

Recall top_rated[i] is a queue_entry, we see that there is winner for this bit.

      u32 j = MAP_SIZE >> 3;
      /* Remove all bits belonging to the current entry from temp_v. */
      while (j--)
        if (top_rated[i]->trace_mini[j])
          temp_v[j] &= ~top_rated[i]->trace_mini[j];

Aggregate all bits of the current item into temp_v[].

      top_rated[i]->favored = 1;
      queued_favored++;

      if (!top_rated[i]->was_fuzzed) pending_favored++;
    }

Favor the item, increment the counter, if not fuzzed already, order to do so.

  q = queue;
  while (q) {
    mark_as_redundant(q, !q->favored);
    q = q->next;
  }
}

The above basically saves the information into the filesystem. mark_as_redundant() will create a file in output/queue/.state/redundant_edges/ directory for the queue item and the next load will notice the file and restore.

Let’s revisit the main fuzzing loop in main().

  while (1) {
    u8 skipped_fuzz;
    cull_queue();

    if (!queue_cur) {

Current queue item is empty when we start. queue denotes the loaded test cases.

      queue_cycle++;
      current_entry     = 0;
      cur_skipped_paths = 0;
      queue_cur         = queue;

      while (seek_to) {
        current_entry++;
        seek_to--;
        queue_cur = queue_cur->next;
      }

      show_stats();

      if (not_on_tty) {
        ACTF("Entering queue cycle %llu.", queue_cycle);
        fflush(stdout);
      }

      /* If we had a full queue cycle with no new finds, try
         recombination strategies next. */
      if (queued_paths == prev_queued) {
        if (use_splicing) cycles_wo_finds++; else use_splicing = 1;
      } else cycles_wo_finds = 0;

This enables splicing since we have a cycle without findings.

      prev_queued = queued_paths;
      if (sync_id && queue_cycle == 1 && getenv("AFL_IMPORT_FIRST"))
        sync_fuzzers(use_argv);
    }

Multi-core related, I will visit this in particular section later.

    skipped_fuzz = fuzz_one(use_argv); // fuzz one

Execute the fuzzer and set the current item to the next one in the queue.

    if (!stop_soon && sync_id && !skipped_fuzz) {
      if (!(sync_interval_cnt++ % SYNC_INTERVAL))
        sync_fuzzers(use_argv);
    }
    if (!stop_soon && exit_1) stop_soon = 2;
    if (stop_soon) break;

    queue_cur = queue_cur->next;
    current_entry++;
  }

Let’s see the prologue of fuzz_one() and see how skipping works.

static u8 fuzz_one(char** argv) {
  s32 len, fd, temp_len, i, j;
  u8  *in_buf, *out_buf, *orig_in, *ex_tmp, *eff_map = 0;
  u64 havoc_queued,  orig_hit_cnt, new_hit_cnt;
  u32 splice_cycle = 0, perf_score = 100, orig_perf, prev_cksum, eff_cnt = 1;
  u8  ret_val = 1, doing_det = 0;
  u8  a_collect[MAX_AUTO_EXTRA];
  u32 a_len = 0;

#ifdef IGNORE_FINDS
  .. skipd for brevity ..
#else
  if (pending_favored) {
    if ((queue_cur->was_fuzzed || !queue_cur->favored) &&
        UR(100) < SKIP_TO_NEW_PROB) return 1;

If we have a favored item pending, skip if we already fuzzed or if it is not favored probabilistly. Recall UR(100) picks a random number between 0 and 99 inclusively. Interesting enough, SKIP_TO_NEW_PROB is defined to be 99 in config.h, so this is true only 99 percent of the time.

  } else if (!dumb_mode && !queue_cur->favored && queued_paths > 10) {
    if (queue_cycle > 1 && !queue_cur->was_fuzzed) {
      if (UR(100) < SKIP_NFAV_NEW_PROB) return 1;
    } else {
      if (UR(100) < SKIP_NFAV_OLD_PROB) return 1;
    }
  }
#endif /* ^IGNORE_FINDS */

The above also skips non-favored items probablistly. If we are not in the first cycle, we skip according to SKIP_NFAV_NEW_PROB, otherwise, we skip according to SKIP_NFAV_OLD_PROB. The constants are defined in config.h as follows:

#define SKIP_NFAV_OLD_PROB  95 /* ...no new favs, cur entry already fuzzed */
#define SKIP_NFAV_NEW_PROB  75 /* ...no new favs, cur entry not fuzzed yet */

It can be observed that old items are skipped 95 percent and new items are skipped only 75 percent. The rest of the function is discussed in the Stages section.

Trimming

After calibration is done, there is a also a trimming stage. Let’s see how it works.

  /************
   * TRIMMING *
   ************/
  if (!dumb_mode && !queue_cur->trim_done) {
    u8 res = trim_case(argv, queue_cur, in_buf);
    if (res == FAULT_ERROR)
      FATAL("Unable to execute target application");

    if (stop_soon) {
      cur_skipped_paths++;
      goto abandon_entry;
    }
    /* Don't retry trimming, even if it failed. */
    queue_cur->trim_done = 1;
    if (len != queue_cur->len) len = queue_cur->len;
  }

This is the call site in fuzz_one(). It invokes trimming on the current queue item. Let’s see the definition.

/* Trim all new test cases to save cycles when doing deterministic checks. The
   trimmer uses power-of-two increments somewhere between 1/16 and 1/1024 of
   file size, to keep the stage short and sweet. */
static u8 trim_case(char** argv, struct queue_entry* q, u8* in_buf) {
  static u8 tmp[64];
  static u8 clean_trace[MAP_SIZE];

  u8  needs_write = 0, fault = 0;
  u32 trim_exec = 0;
  u32 remove_len;
  u32 len_p2;

  /* Although the trimmer will be less useful when variable behavior is
     detected, it will still work to some extent, so we don't check for
     this. */
  if (q->len < 5) return 0;

Skip if length is less than 5 bytes.

  stage_name = tmp;

Seems like tmp is not initialized :(

  bytes_trim_in += q->len;
  /* Select initial chunk len, starting with large steps. */
  len_p2 = next_p2(q->len);

First power of two larger than q->len.

  remove_len = MAX(len_p2 / TRIM_START_STEPS, TRIM_MIN_BYTES);

So these constants are defined in config.h as follows:

#define TRIM_MIN_BYTES      4
#define TRIM_START_STEPS    16
#define TRIM_END_STEPS      1024

Let’s do an example. Say q->len is 127. Then, p2 is 128=2^7. remove_len will be MAX(128/16, 4) which is 8. Similarly, MAX(len_p2/TRIM_END_STEPS, TRIM_MIN_BYTES)=MAX(128/1024, 4)=4. stage_max will be 127/8=8.

  /* Continue until the number of steps gets too high or the stepover
     gets too small. */
  while (remove_len >= MAX(len_p2 / TRIM_END_STEPS, TRIM_MIN_BYTES)) {
    u32 remove_pos = remove_len;
    sprintf(tmp, "trim %s/%s", DI(remove_len), DI(remove_len));
    stage_cur = 0;
    stage_max = q->len / remove_len;
    while (remove_pos < q->len) {
      u32 trim_avail = MIN(remove_len, q->len - remove_pos);

trim_avail will be MIN(8, 127-8)=8.

      u32 cksum;
      write_with_gap(in_buf, q->len, remove_pos, trim_avail);

The above function has the following prototype:

static void write_with_gap(void* mem, u32 len, u32 skip_at, u32 skip_len);

write_with_gap() omits the data between skip_at and skip_at+skip_len in the buffer pointed by mem. So the loop basically modifies the buffer by skipping trim_avail bytes at position remove_pos.

      fault = run_target(argv, exec_tmout);
      trim_execs++;
      if (stop_soon || fault == FAULT_ERROR) goto abort_trimming;
      /* Note that we don't keep track of crashes or hangs here; maybe TODO? */
      cksum = hash32(trace_bits, MAP_SIZE, HASH_CONST);
      /* If the deletion had no impact on the trace, make it permanent. This
         isn't perfect for variable-path inputs, but we're just making a
         best-effort pass, so it's not a big deal if we end up with false
         negatives every now and then. */
      if (cksum == q->exec_cksum) {

Run the target and check whether the checksum is modified. If it is not then, modify the input buffer to reflect that change and flag needs_write.

        u32 move_tail = q->len - remove_pos - trim_avail;

        q->len -= trim_avail;
        len_p2  = next_p2(q->len);

        memmove(in_buf + remove_pos, in_buf + remove_pos + trim_avail,
                move_tail);
        /* Let's save a clean trace, which will be needed by
           update_bitmap_score once we're done with the trimming stuff. */
        if (!needs_write) {
          needs_write = 1;
          memcpy(clean_trace, trace_bits, MAP_SIZE);
        }
      } else remove_pos += remove_len;
      /* Since this can be slow, update the screen every now and then. */
      if (!(trim_exec++ % stats_update_freq)) show_stats();
      stage_cur++;
    }

remove_len will be 4 in the next loop.

    remove_len >>= 1;
  }
  /* If we have made changes to in_buf, we also need to update the on-disk
     version of the test case. */
  if (needs_write) {
    s32 fd;
    unlink(q->fname); /* ignore errors */
    fd = open(q->fname, O_WRONLY | O_CREAT | O_EXCL, 0600);
    if (fd < 0) PFATAL("Unable to create '%s'", q->fname);
    ck_write(fd, in_buf, q->len, q->fname);
    close(fd);
    memcpy(trace_bits, clean_trace, MAP_SIZE);
    update_bitmap_score(q);
  }
abort_trimming:
  bytes_trim_out += q->len;
  return fault;
}

Finally, the new buffer will be written to a file while the old one is unlinked.

Initial Values and show_init_stats()

It is time for the user inerfaces. This function is called in main() and it initializes common parameters like timeout, havoc_div. Let’s see the details.

/* Display quick statistics at the end of processing the input directory,
   plus a bunch of warnings. Some calibration stuff also ended up here,
   along with several hardcoded constants. Maybe clean up eventually. */
static void show_init_stats(void) {
  struct queue_entry* q = queue;
  u32 min_bits = 0, max_bits = 0;
  u64 min_us = 0, max_us = 0;
  u64 avg_us = 0;
  u32 max_len = 0;

  if (total_cal_cycles) avg_us = total_cal_us / total_cal_cycles;

Set the average execution time based on the calibration stage.

  while (q) {
    if (!min_us || q->exec_us < min_us) min_us = q->exec_us;
    if (q->exec_us > max_us) max_us = q->exec_us;

    if (!min_bits || q->bitmap_size < min_bits) min_bits = q->bitmap_size;
    if (q->bitmap_size > max_bits) max_bits = q->bitmap_size;

    if (q->len > max_len) max_len = q->len;

    q = q->next;
  }
  SAYF("\n");

Set minimum, maximum execution times. Set minimum and maximum bitmap sizes. Set maximum input length in the queue.

  if (avg_us > (qemu_mode ? 50000 : 10000))
    WARNF(cLRD "The target binary is pretty slow! See %s/perf_tips.txt.",
          doc_path);

Warn if average execution time is over 10ms.

  /* Let's keep things moving with slow binaries. */
  if (avg_us > 50000) havoc_div = 10;     /* 0-19 execs/sec   */
  else if (avg_us > 20000) havoc_div = 5; /* 20-49 execs/sec  */
  else if (avg_us > 10000) havoc_div = 2; /* 50-100 execs/sec */

Adjust havoc_div according to the average execution time.

  if (!resuming_fuzz) {
    if (max_len > 50 * 1024)
      WARNF(cLRD "Some test cases are huge (%s) - see %s/perf_tips.txt!",
            DMS(max_len), doc_path);
    else if (max_len > 10 * 1024)
      WARNF("Some test cases are big (%s) - see %s/perf_tips.txt.",
            DMS(max_len), doc_path);

    if (useless_at_start && !in_bitmap)
      WARNF(cLRD "Some test cases look useless. Consider using a smaller set.");

    if (queued_paths > 100)
      WARNF(cLRD "You probably have far too many input files! Consider trimming down.");
    else if (queued_paths > 20)
      WARNF("You have lots of input files; try starting small.");
  }

These let us know if we are walking over the limits. Basically, it suggests that, 50KiB test cases are huge and it is better to keep them under 10KiB. Besides, if there are more than 100 initial items, it is better to run minimization (ie. afl-cmin, afl-tmin) over the input directory. Finally, it is also advised to start with less than 20 test cases, otherwise we get a warning.

  OKF("Here are some useful stats:\n\n"
      cGRA "   Test case count:" cRST "%u favored, %u variable, %u total\n"
      cGRA "      Bitmap range:" cRST "%u to %u bits (average: %0.02f bits)\n"
      cGRA "       Exec timing:" cRST "%s to %s us (average: %s us)\n",
      queued_favored, queued_variable, queued_paths, min_bits, max_bits,
      ((double)total_bitmap_size) /
      (total_bitmap_entries ? total_bitmap_entries : 1),
      DI(min_us), DI(max_us), DI(avg_us));

Let’s describe these variables:

  if (!timeout_given) {
    /* Figure out the appropriate timeout. The basic idea is: 5x average or
       1x max, rounded up to EXEC_TM_ROUND ms and capped at 1 second.

       If the program is slow, the multiplier is lowered to 2x or 3x, because
       random scheduler jitter is less likely to have any impact, and because
       our patience is wearing thin =) */
    if (avg_us > 50000) exec_tmout = avg_us * 2 / 1000;
    else if (avg_us > 10000) exec_tmout = avg_us * 3 / 1000;
    else exec_tmout = avg_us * 5 / 1000;

    exec_tmout = MAX(exec_tmout, max_us / 1000);
    exec_tmout = (exec_tmout + EXEC_TM_ROUND) / EXEC_TM_ROUND * EXEC_TM_ROUND;

    if (exec_tmout > EXEC_TIMEOUT) exec_tmout = EXEC_TIMEOUT;

    ACTF("No -t option specified, so I'll use exec timeout of %u ms.",
         exec_tmout);

    timeout_given = 1;
  } else if (timeout_given == 3) {
    ACTF("Applying timeout settings from resumed session (%u ms).",
                   exec_tmout);
  }

The above code tries to figure out a sane timeout value. This value is in milliseconds and upper bounded by EXEC_TIMEOUT defined in config.h as 1000ms.

  /* In dumb mode, re-running every timing out test case with a generous time
     limit is very expensive, so let's select a more conservative default. */
  if (dumb_mode && !getenv("AFL_HANG_TMOUT"))
    hang_tmout = MIN(EXEC_TIMEOUT, exec_tmout * 2 + 100);

  OKF("All set and ready to roll!");
}

Timeout value also can be provided by an environment variable called AFL_HANG_TMOUT.

show_stats()

This is the last function covered in this article. It is called in various places to update the UI and adjust several parameters. Frequency depends on stats_update_freq.

static void show_stats(void) {
 static u64 last_stats_ms, last_plot_ms, last_ms, last_execs;
 static double avg_exec;
 double t_byte_ratio, stab_ratio;

 u64 cur_ms;
 u32 t_bytes, t_bits;

 u32 banner_len, banner_pad;
 u8  tmp[256];

 cur_ms = get_cur_time();

Mark the moment.

 /* If not enough time has passed since last UI update, bail out. */
 if (cur_ms - last_ms < 1000 / UI_TARGET_HZ) return;

UI_TARGET_HZ is defined to be 5 in config.h so 1000/UI_TARGET_HZ is 0.2 seconds.

 /* Check if we're past the 10 minute mark. */
 if (cur_ms - start_time > 10 * 60 * 1000) run_over10m = 1;

Mark if we are running over 10 minutes. This is used in havoc/splice stages.

 /* Calculate smoothed exec speed stats. */
 if (!last_execs) {
   avg_exec = ((double)total_execs) * 1000 / (cur_ms - start_time);
 } else {
   double cur_avg = ((double)(total_execs - last_execs)) * 1000 /
                    (cur_ms - last_ms);
   /* If there is a dramatic (5x+) jump in speed, reset the indicator
      more quickly. */
   if (cur_avg * 5 < avg_exec || cur_avg / 5 > avg_exec)
     avg_exec = cur_avg;

   avg_exec = avg_exec * (1.0 - 1.0 / AVG_SMOOTHING) +
              cur_avg * (1.0 / AVG_SMOOTHING);
 }

Calculate average execution time.

 last_ms = cur_ms;
 last_execs = total_execs;

Save state for later use.

 /* Tell the callers when to contact us (as measured in execs). */
 stats_update_freq = avg_exec / (UI_TARGET_HZ * 10);
 if (!stats_update_freq) stats_update_freq = 1;

Calculate call frequency, avg_exec/50.

 /* Do some bitmap stats. */
 t_bytes = count_non_255_bytes(virgin_bits);
 t_byte_ratio = ((double)t_bytes * 100) / MAP_SIZE;

 if (t_bytes)
   stab_ratio = 100 - ((double)var_byte_count) * 100 / t_bytes;
 else
   stab_ratio = 100;

Calculate t_bytes by counting !=255 bytes. stab_ratio is the stability ratio. This variable depends on the number of variable bytes, more variable bytes more instability.

 /* Roughly every minute, update fuzzer stats and save auto tokens. */
 if (cur_ms - last_stats_ms > STATS_UPDATE_SEC * 1000) {
   last_stats_ms = cur_ms;
   write_stats_file(t_byte_ratio, stab_ratio, avg_exec);
   save_auto();
   write_bitmap();
 }

Save stats in stats file, save auto collected token, save bitmap. Period is determined by STATS_UPDATE_SEC and it is defined in config.h as 60.

 /* Every now and then, write plot data. */
 if (cur_ms - last_plot_ms > PLOT_UPDATE_SEC * 1000) {
   last_plot_ms = cur_ms;
   maybe_update_plot_file(t_byte_ratio, avg_exec);
 }

Update the plot file. The period is determined by PLOT_UPDATE_SEC defined in config.h as 5.

 /* Honor AFL_EXIT_WHEN_DONE and AFL_BENCH_UNTIL_CRASH. */
 if (!dumb_mode && cycles_wo_finds > 100 && !pending_not_fuzzed &&
     getenv("AFL_EXIT_WHEN_DONE")) stop_soon = 2;

This is interesting. It allows the fuzzer to quit if 100 cycles passed without any finds and enabled by environment variabled called AFL_EXIT_WHEN_DONE.

 if (total_crashes && getenv("AFL_BENCH_UNTIL_CRASH")) stop_soon = 2;

This allows the fuzzer quit if AFL_BENCH_UNTIL_CRASH is defined and target crashes.

 /* If we're not on TTY, bail out. */
 if (not_on_tty) return;
 /* Compute some mildly useful bitmap stats. */
 t_bits = (MAP_SIZE << 3) - count_bits(virgin_bits);

Save the bitcount in t_bits. count_bits() is a nice popcount implementation.

 /* Now, for the visuals... */
 if (clear_screen) {
   SAYF(TERM_CLEAR CURSOR_HIDE);
   clear_screen = 0;
   check_term_size();
 }
 SAYF(TERM_HOME);
 if (term_too_small) {
   SAYF(cBRI "Your terminal is too small to display the UI.\n"
        "Please resize terminal window to at least 80x25.\n" cRST);
   return;
 }
 /* Let's start by drawing a centered banner. */
 banner_len = (crash_mode ? 24 : 22) + strlen(VERSION) + strlen(use_banner);
 banner_pad = (80 - banner_len) / 2;
 memset(tmp, ' ', banner_pad);

 sprintf(tmp + banner_pad, "%s " cLCY VERSION cLGN
         " (%s)",  crash_mode ? cPIN "peruvian were-rabbit" :
         cYEL "american fuzzy lop", use_banner);

 SAYF("\n%s\n\n", tmp);
 /* "Handy" shortcuts for drawing boxes... */
#define bSTG    bSTART cGRA
#define bH2     bH bH
#define bH5     bH2 bH2 bH
#define bH10    bH5 bH5
#define bH20    bH10 bH10
#define bH30    bH20 bH10
#define SP5     "     "
#define SP10    SP5 SP5
#define SP20    SP10 SP10

Clear the terminal, check the terminal size, complain if too small, show the banner.

 /* Lord, forgive me this. */
 SAYF(SET_G1 bSTG bLT bH bSTOP cCYA " process timing " bSTG bH30 bH5 bH2 bHB
      bH bSTOP cCYA " overall results " bSTG bH5 bRT "\n");

 if (dumb_mode) {
   strcpy(tmp, cRST);
 } else {
   u64 min_wo_finds = (cur_ms - last_path_time) / 1000 / 60;
   /* First queue cycle: don't stop now! */
   if (queue_cycle == 1 || min_wo_finds < 15) strcpy(tmp, cMGN); else
   /* Subsequent cycles, but we're still making finds. */
   if (cycles_wo_finds < 25 || min_wo_finds < 30) strcpy(tmp, cYEL); else
   /* No finds for a long time and no test cases to try. */
   if (cycles_wo_finds > 100 && !pending_not_fuzzed && min_wo_finds > 120)
     strcpy(tmp, cLGN);
   /* Default: cautiously OK to stop? */
   else strcpy(tmp, cLBL);
 }

min_wo_finds is the time passed since the last path discovery. The rest is for coloring cycles_done. It is magenta if we are in the first cycle or we have found a path in the last 15 hours. It is yellow, if we have not found a new path for 25 cycles or in the last 30 hours. Finally it is light green if we haven’t found for 100 cycles, no new items in the queue and no new paths for 120 hours. This indicates the fuzzer is failing to discover new paths.

 SAYF(bV bSTOP "        run time : " cRST "%-34s " bSTG bV bSTOP
      "  cycles done : %s%-5s  " bSTG bV "\n",
      DTD(cur_ms, start_time), tmp, DI(queue_cycle - 1));

Show the runtime. DTD() is short for describe time delta and DI() is short for describe integer.

 /* We want to warn people about not seeing new paths after a full cycle,
    except when resuming fuzzing or running in non-instrumented mode. */
 if (!dumb_mode && (last_path_time || resuming_fuzz || queue_cycle == 1 ||
     in_bitmap || crash_mode)) {
   SAYF(bV bSTOP "   last new path : " cRST "%-34s ",
        DTD(cur_ms, last_path_time));
 } else {
   if (dumb_mode)
     SAYF(bV bSTOP "   last new path : " cPIN "n/a" cRST
          " (non-instrumented mode)        ");
    else
     SAYF(bV bSTOP "   last new path : " cRST "none yet " cLRD
          "(odd, check syntax!)      ");
 }
 SAYF(bSTG bV bSTOP "  total paths : " cRST "%-5s  " bSTG bV "\n",
      DI(queued_paths));

Now show the last_path_time and queued_paths.

 /* Highlight crashes in red if found, denote going over the KEEP_UNIQUE_CRASH
    limit with a '+' appended to the count. */
 sprintf(tmp, "%s%s", DI(unique_crashes),
         (unique_crashes >= KEEP_UNIQUE_CRASH) ? "+" : "");

 SAYF(bV bSTOP " last uniq crash : " cRST "%-34s " bSTG bV bSTOP
      " uniq crashes : %s%-6s " bSTG bV "\n",
      DTD(cur_ms, last_crash_time), unique_crashes ? cLRD : cRST,
      tmp);

Show last_crash_time and the number of unique crashes. It becomes light red if the fuzzer discovered a crash already.

 sprintf(tmp, "%s%s", DI(unique_hangs),
        (unique_hangs >= KEEP_UNIQUE_HANG) ? "+" : "");

 SAYF(bV bSTOP "  last uniq hang : " cRST "%-34s " bSTG bV bSTOP
      "   uniq hangs : " cRST "%-6s " bSTG bV "\n",
      DTD(cur_ms, last_hang_time), tmp);

Show last_hang_time and the number of unique timeouts.

 SAYF(bVR bH bSTOP cCYA " cycle progress " bSTG bH20 bHB bH bSTOP cCYA
      " map coverage " bSTG bH bHT bH20 bH2 bH bVL "\n");

Header for cycle progress and coverage.

 /* This gets funny because we want to print several variable-length variables
    together, but then cram them into a fixed-width field - so we need to
    put them in a temporary buffer first. */

 sprintf(tmp, "%s%s (%0.02f%%)", DI(current_entry),
         queue_cur->favored ? "" : "*",
         ((double)current_entry * 100) / queued_paths);

 SAYF(bV bSTOP "  now processing : " cRST "%-17s " bSTG bV bSTOP, tmp);

 sprintf(tmp, "%0.02f%% / %0.02f%%", ((double)queue_cur->bitmap_size) *
         100 / MAP_SIZE, t_byte_ratio);

 SAYF("    map density : %s%-21s " bSTG bV "\n", t_byte_ratio > 70 ? cLRD :
      ((t_bytes < 200 && !dumb_mode) ? cPIN : cRST), tmp);

Now, show cycle progress. current_entry is the unique ID of the item in the queue. queued_paths is the total number of items in the queue. Next, show map density. Recall, queue_cur->bitmap_size is the number of bits in that particular item. t_byte_ratio is t_bytes (ie. count_non_255_bytes()) as percentage over the total MAP_SIZE >> 3.

 sprintf(tmp, "%s (%0.02f%%)", DI(cur_skipped_paths),
         ((double)cur_skipped_paths * 100) / queued_paths);

 SAYF(bV bSTOP " paths timed out : " cRST "%-17s " bSTG bV, tmp);

 sprintf(tmp, "%0.02f bits/tuple",
         t_bytes ? (((double)t_bits) / t_bytes) : 0);

 SAYF(bSTOP " count coverage : " cRST "%-21s " bSTG bV "\n", tmp);

cur_skipped_paths is the number of skipped paths. This counter is incremented in common_fuzz_stuff() if it encounters a timeout. Moreover, users can skip an item in the queue by sending SIGUSR1 signal during fuzzing. Show this number and its percentage over the total. counter coverage is the ratio of total bits over total bytes. This measures the entropy of the target.

 SAYF(bVR bH bSTOP cCYA " stage progress " bSTG bH20 bX bH bSTOP cCYA
      " findings in depth " bSTG bH20 bVL "\n");

Headers for stage progress and findings.

 sprintf(tmp, "%s (%0.02f%%)", DI(queued_favored),
         ((double)queued_favored) * 100 / queued_paths);

 SAYF(bV bSTOP "  now trying : " cRST "%-21s " bSTG bV bSTOP
      " favored paths : " cRST "%-22s " bSTG bV "\n", stage_name, tmp);

Show the stage name and favored paths and its ratio.

 if (!stage_max) {
   sprintf(tmp, "%s/-", DI(stage_cur));
 } else {
   sprintf(tmp, "%s/%s (%0.02f%%)", DI(stage_cur), DI(stage_max),
           ((double)stage_cur) * 100 / stage_max);
 }
 SAYF(bV bSTOP " stage execs : " cRST "%-21s " bSTG bV bSTOP, tmp);

Tell the user about the current stage and its total stages.

 sprintf(tmp, "%s (%0.02f%%)", DI(queued_with_cov),
         ((double)queued_with_cov) * 100 / queued_paths);
 SAYF("  new edges on : " cRST "%-22s " bSTG bV "\n", tmp);

Show the number of items with coverage and its ratio over the total.

 sprintf(tmp, "%s (%s%s unique)", DI(total_crashes), DI(unique_crashes),
         (unique_crashes >= KEEP_UNIQUE_CRASH) ? "+" : "");

 if (crash_mode) {
   SAYF(bV bSTOP " total execs : " cRST "%-21s " bSTG bV bSTOP
        "   new crashes : %s%-22s " bSTG bV "\n", DI(total_execs),
        unique_crashes ? cLRD : cRST, tmp);
 } else {
   SAYF(bV bSTOP " total execs : " cRST "%-21s " bSTG bV bSTOP
        " total crashes : %s%-22s " bSTG bV "\n", DI(total_execs),
        unique_crashes ? cLRD : cRST, tmp);
 }

Show the total number of crashes and number of unique crashes that lead to distinct bitmaps. If unique_crashes > 0 then it is displayed in light red.

 /* Show a warning about slow execution. */
 if (avg_exec < 100) {
   sprintf(tmp, "%s/sec (%s)", DF(avg_exec), avg_exec < 20 ?
           "zzzz..." : "slow!");

   SAYF(bV bSTOP "  exec speed : " cLRD "%-21s ", tmp);
 } else {
   sprintf(tmp, "%s/sec", DF(avg_exec));
   SAYF(bV bSTOP "  exec speed : " cRST "%-21s ", tmp);
 }

Tell the user about the execution speed. DF is for describe float. Execution speed is very slow (ie. “zzz”) if it is less than 20 execs/sec. It is slow if it is less than 100 execs/sec.

 sprintf(tmp, "%s (%s%s unique)", DI(total_tmouts), DI(unique_tmouts),
         (unique_hangs >= KEEP_UNIQUE_HANG) ? "+" : "");

 SAYF (bSTG bV bSTOP "  total tmouts : " cRST "%-22s " bSTG bV "\n", tmp);

Show the total number of timeouts. Put a little plus sign if we have more than KEEP_UNIQUE_HANG which is defined to be 500 in config.h.

 /* Aaaalmost there... hold on! */
 SAYF(bVR bH cCYA bSTOP " fuzzing strategy yields " bSTG bH10 bH bHT bH10
      bH5 bHB bH bSTOP cCYA " path geometry " bSTG bH5 bH2 bH bVL "\n");

Headers for strategy yields and path geometry.

 if (skip_deterministic) {
   strcpy(tmp, "n/a, n/a, n/a");
 } else {
   sprintf(tmp, "%s/%s, %s/%s, %s/%s",
           DI(stage_finds[STAGE_FLIP1]), DI(stage_cycles[STAGE_FLIP1]),
           DI(stage_finds[STAGE_FLIP2]), DI(stage_cycles[STAGE_FLIP2]),
           DI(stage_finds[STAGE_FLIP4]), DI(stage_cycles[STAGE_FLIP4]));
 }

 SAYF(bV bSTOP "   bit flips : " cRST "%-37s " bSTG bV bSTOP "    levels : "
      cRST "%-10s " bSTG bV "\n", tmp, DI(max_depth));

Show bitflip stage yields. Show the maximum depth in the queue. Recall that, depth counter is an increment of the depth of the parent queue item and it is monotonic.

 if (!skip_deterministic)
   sprintf(tmp, "%s/%s, %s/%s, %s/%s",
           DI(stage_finds[STAGE_FLIP8]), DI(stage_cycles[STAGE_FLIP8]),
           DI(stage_finds[STAGE_FLIP16]), DI(stage_cycles[STAGE_FLIP16]),
           DI(stage_finds[STAGE_FLIP32]), DI(stage_cycles[STAGE_FLIP32]));

 SAYF(bV bSTOP "  byte flips : " cRST "%-37s " bSTG bV bSTOP "   pending : "
      cRST "%-10s " bSTG bV "\n", tmp, DI(pending_not_fuzzed));

Show bitflip stage yields. Tell the number of pending items in the queue.

 if (!skip_deterministic)
   sprintf(tmp, "%s/%s, %s/%s, %s/%s",
           DI(stage_finds[STAGE_ARITH8]), DI(stage_cycles[STAGE_ARITH8]),
           DI(stage_finds[STAGE_ARITH16]), DI(stage_cycles[STAGE_ARITH16]),
           DI(stage_finds[STAGE_ARITH32]), DI(stage_cycles[STAGE_ARITH32]));

 SAYF(bV bSTOP " arithmetics : " cRST "%-37s " bSTG bV bSTOP "  pend fav : "
      cRST "%-10s " bSTG bV "\n", tmp, DI(pending_favored));

Show arithmetic stage yields. Tell about favored items in the queue.

 if (!skip_deterministic)
   sprintf(tmp, "%s/%s, %s/%s, %s/%s",
      DI(stage_finds[STAGE_INTEREST8]), DI(stage_cycles[STAGE_INTEREST8]),
      DI(stage_finds[STAGE_INTEREST16]), DI(stage_cycles[STAGE_INTEREST16]),
      DI(stage_finds[STAGE_INTEREST32]), DI(stage_cycles[STAGE_INTEREST32]));

 SAYF(bV bSTOP "  known ints : " cRST "%-37s " bSTG bV bSTOP " own finds : "
      cRST "%-10s " bSTG bV "\n", tmp, DI(queued_discovered));

Show interesting stage yields. Tell about newly discovered items in the queue by this particular fuzzer.

 if (!skip_deterministic)
   sprintf(tmp, "%s/%s, %s/%s, %s/%s",
        DI(stage_finds[STAGE_EXTRAS_UO]), DI(stage_cycles[STAGE_EXTRAS_UO]),
        DI(stage_finds[STAGE_EXTRAS_UI]), DI(stage_cycles[STAGE_EXTRAS_UI]),
        DI(stage_finds[STAGE_EXTRAS_AO]), DI(stage_cycles[STAGE_EXTRAS_AO]));

 SAYF(bV bSTOP "  dictionary : " cRST "%-37s " bSTG bV bSTOP
      "  imported : " cRST "%-10s " bSTG bV "\n", tmp,
      sync_id ? DI(queued_imported) : (u8*)"n/a");

Show the extras stage yields. Tell about the imported items in the queue. These are the items found by other fuzzer instances. We will discuss how this works in multi-core fuzzing.

 sprintf(tmp, "%s/%s, %s/%s",
         DI(stage_finds[STAGE_HAVOC]), DI(stage_cycles[STAGE_HAVOC]),
         DI(stage_finds[STAGE_SPLICE]), DI(stage_cycles[STAGE_SPLICE]));

 SAYF(bV bSTOP "       havoc : " cRST "%-37s " bSTG bV bSTOP, tmp);

Show the havoc/splice stage yields.

 if (t_bytes) sprintf(tmp, "%0.02f%%", stab_ratio);
   else strcpy(tmp, "n/a");

 SAYF(" stability : %s%-10s " bSTG bV "\n",
        (stab_ratio < 85 && var_byte_count > 40)
      ? cLRD : ((queued_variable && (!persistent_mode || var_byte_count > 20))
      ? cMGN : cRST), tmp);

Tell about the stability. Recall, stability is ratio of variable bytes (var_byte_count) over the total bytes (t_bytes).

 if (!bytes_trim_out) {
   sprintf(tmp, "n/a, ");
 } else {
   sprintf(tmp, "%0.02f%%/%s, ",
           ((double)(bytes_trim_in - bytes_trim_out)) * 100 / bytes_trim_in,
           DI(trim_execs));
 }

So here bytes_trim_in is the sum of inputs and bytes_trim_out is the sum after the trimming is done by trim_case(). trim_execs is the count of runs of trim_case().

 if (!blocks_eff_total) {
   u8 tmp2[128];
   sprintf(tmp2, "n/a");
   strcat(tmp, tmp2);
 } else {
   u8 tmp2[128];
   sprintf(tmp2, "%0.02f%%",
           ((double)(blocks_eff_total - blocks_eff_select)) * 100 /
           blocks_eff_total);

   strcat(tmp, tmp2);
 }

 SAYF(bV bSTOP "        trim : " cRST "%-37s " bSTG bVR bH20 bH2 bH2 bRB "\n"
      bLB bH30 bH20 bH2 bH bRB bSTOP cRST RESET_G1, tmp);

The above code tells the user about Effector progress. blocks_eff_total is the total bytes handled by the Effector and blocks_eff_select is the total number of bytes selected by it so that consequent stages skip fuzzing.

 /* Provide some CPU utilization stats. */
 if (cpu_core_count) {
   double cur_runnable = get_runnable_processes();
   u32 cur_utilization = cur_runnable * 100 / cpu_core_count;

   u8* cpu_color = cCYA;

   /* If we could still run one or more processes, use green. */
   if (cpu_core_count > 1 && cur_runnable + 1 <= cpu_core_count)
     cpu_color = cLGN;

   /* If we're clearly oversubscribed, use red. */
   if (!no_cpu_meter_red && cur_utilization >= 150) cpu_color = cLRD;

#ifdef HAVE_AFFINITY
   if (cpu_aff >= 0) {
     SAYF(SP10 cGRA "[cpu%03u:%s%3u%%" cGRA "]\r" cRST,
          MIN(cpu_aff, 999), cpu_color,
          MIN(cur_utilization, 999));
   } else {
     SAYF(SP10 cGRA "   [cpu:%s%3u%%" cGRA "]\r" cRST,
          cpu_color, MIN(cur_utilization, 999));
  }
#else
   SAYF(SP10 cGRA "   [cpu:%s%3u%%" cGRA "]\r" cRST,
        cpu_color, MIN(cur_utilization, 999));
#endif /* ^HAVE_AFFINITY */
 } else SAYF("\r");
 /* Hallelujah! */
 fflush(0);
}

Finally, tell the user about the current CPU utilization.

Conclusion

In this section, we have covered the decision making process that defines the progress of the fuzzer. Moreover, we have seen counters, metrics regarding the execution. The user inferface tells about the progress and it is updated regularly.

Hope you enjoyed it. Until next time!