[libfuzzer] Reduce default verbosity when printing large mutation sequences

[mhlakhani]

Summary

When using a custom mutator (e.g. thrift mutator, similar to LPM)
that calls back into libfuzzer's mutations via LLVMFuzzerMutate, the mutation
sequences needed to achieve new coverage can get prohibitively large.

Printing these large sequences has two downsides:

1. It makes the logs hard to understand for a human.
2. The performance cost slows down fuzzing.

In this patch I change the PrintMutationSequence function to take a max
number of entries, to achieve this goal. I also update PrintStatusForNewUnit
to default to printing only 10 entries, in the default verbosity level (1),
requiring the user to set verbosity to 2 if they want the full mutation
sequence.

I would like feedback on whether this behaviour change is OK, or if there's
another preferred value for the constant (10).

For our use case, turning off verbosity is not an option, as that would also
disable PrintStats() which is very useful for infrastructure that analyzes
the logs in realtime. I imagine most users of libfuzzer always want those logs
in the default.

Test Plan:

I did not see automated tests for this and I am not sure how to add them. I
would appreciate feedback on how to do so.

I built a fuzzer locally with this patch applied to libfuzzer.

When running with the default verbosity, I see logs like this:

#65 NEW    cov: 4799 ft: 10443 corp: 41/1447Kb lim: 64000 exec/s: 1 rss: 575Mb L: 28658/62542 MS: 196 Custom-CrossOver-ChangeBit-EraseBytes-ChangeBit-ChangeBit-ChangeBit-CrossOver-ChangeBit-CrossOver- DE: "\xff\xff\xff\x0e"-"\xfe\xff\xff\x7f"-"\xfe\xff\xff\x7f"-"\x17\x00\x00\x00\x00\x00\x00\x00"-"\x00\x00\x00\xf9"-"\xff\xff\xff\xff"-"\xfa\xff\xff\xff"-"\xf7\xff\xff\xff"-"@\xff\xff\xff\xff\xff\xff\xff"-"E\x00"-
#67 NEW    cov: 4810 ft: 10462 corp: 42/1486Kb lim: 64000 exec/s: 1 rss: 577Mb L: 39823/62542 MS: 135 Custom-CopyPart-ShuffleBytes-ShuffleBytes-ChangeBit-ChangeBinInt-EraseBytes-ChangeBit-ChangeBinInt-ChangeBit- DE: "\x01\x00\x00\x00\x00\x00\x01\xf1"-"\x00\x00\x00\x07"-"\x00\x0d"-"\xfd\xff\xff\xff"-"\xfe\xff\xff\xf4"-"\xe3\xff\xff\xff"-"\xff\xff\xff\xf1"-"\xea\xff\xff\xff"-"\x00\x00\x00\xfd"-"\x01\x00\x00\x05"-

Staring hard at the logs it's clear that the cap of 10 is applied.

When running with verbosity level 2, the logs look like the below:

#66    NEW    cov: 4700 ft: 10188 corp: 37/1186Kb lim: 64000 exec/s: 2 rss: 509Mb L: 47616/61231 MS: 520 Custom-CopyPart-ChangeBinInt-ChangeBit-ChangeByte-EraseBytes-PersAutoDict-CopyPart-ShuffleBytes-ChangeBit-ShuffleBytes-CopyPart-EraseBytes-CopyPart-ChangeBinInt-CopyPart-ChangeByte-ShuffleBytes-ChangeBinInt-ShuffleBytes-ChangeBit-CMP-ShuffleBytes-ChangeBit-CrossOver-ChangeBinInt-ChangeByte-ShuffleBytes-CrossOver-EraseBytes-ChangeBinInt-InsertRepeatedBytes-PersAutoDict-InsertRepeatedBytes-InsertRepeatedBytes-CrossOver-ChangeByte-ShuffleBytes-CopyPart-ShuffleBytes-CopyPart-CrossOver-ChangeBit-ShuffleBytes-CrossOver-PersAutoDict-ChangeByte-ChangeBit-ShuffleBytes-CrossOver-ChangeByte-EraseBytes-CopyPart-ChangeBinInt-PersAutoDict-CrossOver-ShuffleBytes-CrossOver-CrossOver-EraseBytes-CrossOver-EraseBytes-CrossOver-ChangeBit-ChangeBinInt-ChangeByte-EraseBytes-ShuffleBytes-ShuffleBytes-ChangeBit-EraseBytes-ChangeBinInt-ChangeBit-ChangeBinInt-CopyPart-EraseBytes-PersAutoDict-EraseBytes-CopyPart-ChangeBinInt-ChangeByte-CrossOver-ChangeBinInt-ShuffleBytes-PersAutoDict-PersAutoDict-ChangeBinInt-CopyPart-ChangeBinInt-CrossOver-ChangeBit-ChangeBinInt-CopyPart-ChangeByte-ChangeBit-CopyPart-CrossOver-ChangeByte-ChangeBit-ChangeByte-ShuffleBytes-CMP-ChangeBit-CopyPart-ChangeBit-ChangeByte-ChangeBinInt-PersAutoDict-ChangeBinInt-CrossOver-ChangeBinInt-ChangeBit-ChangeBinInt-ChangeBinInt-PersAutoDict-ChangeBinInt-ChangeBinInt-ChangeByte-CopyPart-ShuffleBytes-ChangeByte-ChangeBit-ChangeByte-ChangeByte-EraseBytes-CrossOver-ChangeByte-ChangeByte-EraseBytes-EraseBytes-InsertRepeatedBytes-ShuffleBytes-CopyPart-CopyPart-ChangeBit-ShuffleBytes-PersAutoDict-ShuffleBytes-ChangeBit-ChangeByte-ChangeBit-ShuffleBytes-ChangeByte-ChangeBinInt-CrossOver-ChangeBinInt-ChangeBit-EraseBytes-CopyPart-ChangeByte-CrossOver-EraseBytes-CrossOver-ChangeByte-ShuffleBytes-ChangeByte-ChangeBinInt-CrossOver-ChangeByte-InsertRepeatedBytes-InsertByte-ShuffleBytes-PersAutoDict-ChangeBit-ChangeByte-ChangeBit-ShuffleBytes-ShuffleBytes-CopyPart-ShuffleBytes-EraseBytes-ShuffleBytes-ShuffleBytes-CrossOver-ChangeBinInt-CopyPart-CopyPart-CopyPart-EraseBytes-EraseBytes-ChangeByte-ChangeBinInt-ShuffleBytes-CMP-InsertByte-EraseBytes-ShuffleBytes-CopyPart-ChangeBit-CrossOver-CopyPart-CopyPart-ShuffleBytes-ChangeByte-ChangeByte-ChangeBinInt-EraseBytes-ChangeByte-ChangeBinInt-ChangeBit-ChangeBit-ChangeByte-ShuffleBytes-PersAutoDict-PersAutoDict-CMP-ChangeBit-ShuffleBytes-PersAutoDict-ChangeBinInt-EraseBytes-EraseBytes-ShuffleBytes-ChangeByte-ShuffleBytes-ChangeBit-EraseBytes-CMP-ShuffleBytes-ChangeByte-ChangeBinInt-EraseBytes-ChangeBinInt-ChangeByte-EraseBytes-ChangeByte-CrossOver-ShuffleBytes-EraseBytes-EraseBytes-ShuffleBytes-ChangeBit-EraseBytes-CopyPart-ShuffleBytes-ShuffleBytes-CrossOver-CopyPart-ChangeBinInt-ShuffleBytes-CrossOver-InsertByte-InsertByte-ChangeBinInt-ChangeBinInt-CopyPart-EraseBytes-ShuffleBytes-ChangeBit-ChangeBit-EraseBytes-ChangeByte-ChangeByte-ChangeBinInt-CrossOver-ChangeBinInt-ChangeBinInt-ShuffleBytes-ShuffleBytes-ChangeByte-ChangeByte-ChangeBinInt-ShuffleBytes-CrossOver-EraseBytes-CopyPart-CopyPart-CopyPart-ChangeBit-ShuffleBytes-ChangeByte-EraseBytes-ChangeByte-InsertRepeatedBytes-InsertByte-InsertRepeatedBytes-PersAutoDict-EraseBytes-ShuffleBytes-ChangeByte-ShuffleBytes-ChangeBinInt-ShuffleBytes-ChangeBinInt-ChangeBit-CrossOver-CrossOver-ShuffleBytes-CrossOver-CopyPart-CrossOver-CrossOver-CopyPart-ChangeByte-ChangeByte-CrossOver-ChangeBit-ChangeBinInt-EraseBytes-ShuffleBytes-EraseBytes-CMP-PersAutoDict-PersAutoDict-InsertByte-ChangeBit-ChangeByte-CopyPart-CrossOver-ChangeByte-ChangeBit-ChangeByte-CopyPart-ChangeBinInt-EraseBytes-CrossOver-ChangeBit-CrossOver-PersAutoDict-CrossOver-ChangeByte-CrossOver-ChangeByte-ChangeByte-CrossOver-ShuffleBytes-CopyPart-CopyPart-ShuffleBytes-ChangeByte-ChangeByte-ChangeBinInt-ChangeBinInt-ChangeBinInt-ChangeBinInt-ShuffleBytes-CrossOver-ChangeBinInt-ShuffleBytes-ChangeBit-PersAutoDict-ChangeBinInt-ShuffleBytes-ChangeBinInt-ChangeByte-CrossOver-ChangeBit-CopyPart-ChangeBit-ChangeBit-CopyPart-ChangeByte-PersAutoDict-ChangeBit-ShuffleBytes-ChangeByte-ChangeBit-CrossOver-ChangeByte-CrossOver-ChangeByte-CrossOver-ChangeBit-ChangeByte-ChangeBinInt-PersAutoDict-CopyPart-ChangeBinInt-ChangeBit-CrossOver-ChangeBit-PersAutoDict-ShuffleBytes-EraseBytes-CrossOver-ChangeByte-ChangeBinInt-ShuffleBytes-ChangeBinInt-InsertRepeatedBytes-PersAutoDict-CrossOver-ChangeByte-Custom-PersAutoDict-CopyPart-CopyPart-ChangeBinInt-ShuffleBytes-ChangeBinInt-ChangeBit-ShuffleBytes-CrossOver-CMP-ChangeByte-CopyPart-ShuffleBytes-CopyPart-CopyPart-CrossOver-CrossOver-CrossOver-ShuffleBytes-ChangeByte-ChangeBinInt-ChangeBit-ChangeBit-ChangeBit-ChangeByte-EraseBytes-ChangeByte-ChangeBit-ChangeByte-ChangeByte-CopyPart-PersAutoDict-ChangeBinInt-PersAutoDict-PersAutoDict-PersAutoDict-CopyPart-CopyPart-CrossOver-ChangeByte-ChangeBinInt-ShuffleBytes-ChangeBit-CopyPart-EraseBytes-CopyPart-CopyPart-CrossOver-ChangeByte-EraseBytes-ShuffleBytes-ChangeByte-CopyPart-EraseBytes-CopyPart-CrossOver-ChangeBinInt-ChangeBinInt-InsertByte-ChangeBinInt-ChangeBit-ChangeByte-CopyPart-ChangeByte-EraseBytes-ChangeByte-ChangeBit-ChangeByte-ShuffleBytes-CopyPart-ChangeBinInt-EraseBytes-CrossOver-ChangeBit-ChangeBit-CrossOver-EraseBytes-ChangeBinInt-CopyPart-CopyPart-ChangeBinInt-ChangeBit-EraseBytes-InsertRepeatedBytes-EraseBytes-ChangeBit-CrossOver-CrossOver-EraseBytes-EraseBytes-ChangeByte-CopyPart-CopyPart-ShuffleBytes-ChangeByte-ChangeBit-ChangeByte-EraseBytes-ChangeBit-ChangeByte-ChangeByte-CrossOver-CopyPart-EraseBytes-ChangeByte-EraseBytes-ChangeByte-ShuffleBytes-ShuffleBytes-ChangeByte-CopyPart-ChangeByte-ChangeByte-ChangeBit-CopyPart-ChangeBit-ChangeBinInt-CopyPart-ShuffleBytes-ChangeBit-ChangeBinInt-ChangeBit-EraseBytes-CMP-CrossOver-CopyPart-ChangeBinInt-CrossOver-CrossOver-CopyPart-CrossOver-CrossOver-InsertByte-InsertByte-CopyPart-Custom- DE: "warn"-"\x00\x00\x00\x80"-"\xfe\xff\xff\xfb"-"\xff\xff"-"\x10\x00\x00\x00"-"\xfe\xff\xff\xff"-"\xff\xff\xff\xf6"-"U\x01\x00\x00\x00\x00\x00\x00"-"\xd9\xff\xff\xff"-"\xfe\xff\xff\xea"-"\xf0\xff\xff\xff"-"\xfc\xff\xff\xff"-"warn"-"\xff\xff\xff\xff"-"\xfe\xff\xff\xfb"-"\x00\x00\x00\x80"-"\xfe\xff\xff\xf1"-"\xfe\xff\xff\xea"-"\x00\x00\x00\x00\x00\x00\x012"-"\xe2\x00"-"\xfb\xff\xff\xff"-"\x00\x00\x00\x00"-"\xe9\xff\xff\xff"-"\xff\xff"-"\x00\x00\x00\x80"-"\x01\x00\x04\xc9"-"\xf0\xff\xff\xff"-"\xf9\xff\xff\xff"-"\xff\xff\xff\xff\xff\xff\xff\x12"-"\xe2\x00"-"\xfe\xff\xff\xff"-"\xfe\xff\xff\xea"-"\xff\xff\xff\xff"-"\xf4\xff\xff\xff"-"\xe9\xff\xff\xff"-"\xf1\xff\xff\xff"-
#48    NEW    cov: 4502 ft: 9151 corp: 27/750Kb lim: 64000 exec/s: 2 rss: 458Mb L: 50772/50772 MS: 259 ChangeByte-ShuffleBytes-ChangeBinInt-ChangeByte-ChangeByte-ChangeByte-ChangeByte-ChangeBit-CopyPart-CrossOver-CopyPart-ChangeByte-CrossOver-CopyPart-ChangeBit-ChangeByte-EraseBytes-ChangeByte-CopyPart-CopyPart-CopyPart-ChangeBit-EraseBytes-ChangeBinInt-CrossOver-CopyPart-CrossOver-CopyPart-ChangeBit-ChangeByte-ChangeBit-InsertByte-CrossOver-InsertRepeatedBytes-InsertRepeatedBytes-InsertRepeatedBytes-ChangeBinInt-EraseBytes-InsertRepeatedBytes-InsertByte-ChangeBit-ShuffleBytes-ChangeBit-ChangeBit-CopyPart-ChangeBit-ChangeByte-CrossOver-ChangeBinInt-ChangeByte-CrossOver-CMP-ChangeByte-CrossOver-ChangeByte-ShuffleBytes-ShuffleBytes-ChangeByte-ChangeBinInt-CopyPart-EraseBytes-CrossOver-ChangeBit-ChangeBinInt-InsertByte-ChangeBit-CopyPart-ChangeBinInt-ChangeByte-CrossOver-ChangeBit-EraseBytes-CopyPart-ChangeBinInt-ChangeBit-ChangeBit-ChangeByte-CopyPart-ChangeBinInt-CrossOver-PersAutoDict-ChangeByte-ChangeBit-ChangeByte-ChangeBinInt-ChangeBinInt-EraseBytes-CopyPart-CopyPart-ChangeByte-ChangeByte-EraseBytes-PersAutoDict-CopyPart-ChangeByte-ChangeByte-EraseBytes-CrossOver-CopyPart-CopyPart-CopyPart-ChangeByte-ChangeBit-CMP-CopyPart-ChangeBinInt-ChangeBinInt-CrossOver-ChangeBit-ChangeBit-EraseBytes-ChangeByte-ShuffleBytes-ChangeBit-ChangeBinInt-CMP-InsertRepeatedBytes-CopyPart-Custom-ChangeByte-CrossOver-EraseBytes-ChangeBit-CopyPart-CrossOver-CMP-ShuffleBytes-EraseBytes-CrossOver-PersAutoDict-ChangeByte-CrossOver-CopyPart-CrossOver-CrossOver-ShuffleBytes-ChangeBinInt-CrossOver-ChangeBinInt-ShuffleBytes-PersAutoDict-ChangeByte-EraseBytes-ChangeBit-CrossOver-EraseBytes-CrossOver-ChangeBit-ChangeBinInt-EraseBytes-InsertByte-InsertRepeatedBytes-InsertByte-InsertByte-ChangeByte-ChangeBinInt-ChangeBit-CrossOver-ChangeByte-CrossOver-EraseBytes-ChangeByte-ShuffleBytes-ChangeBit-ChangeBit-ShuffleBytes-CopyPart-ChangeByte-PersAutoDict-ChangeBit-ChangeByte-InsertRepeatedBytes-CMP-CrossOver-ChangeByte-EraseBytes-ShuffleBytes-CrossOver-ShuffleBytes-ChangeBinInt-ChangeBinInt-CopyPart-PersAutoDict-ShuffleBytes-ChangeBit-CopyPart-ShuffleBytes-CopyPart-EraseBytes-ChangeByte-ChangeBit-ChangeBit-ChangeBinInt-ChangeByte-CopyPart-EraseBytes-ChangeBinInt-EraseBytes-EraseBytes-PersAutoDict-CMP-PersAutoDict-CrossOver-CrossOver-ChangeBit-CrossOver-PersAutoDict-CrossOver-CopyPart-ChangeByte-EraseBytes-ChangeByte-ShuffleBytes-ChangeByte-ChangeByte-CrossOver-ChangeBit-EraseBytes-ChangeByte-EraseBytes-ChangeBinInt-CrossOver-CrossOver-EraseBytes-ChangeBinInt-CrossOver-ChangeBit-ShuffleBytes-ChangeBit-ChangeByte-EraseBytes-ChangeBit-CrossOver-CrossOver-CrossOver-ChangeByte-ChangeBit-ShuffleBytes-ChangeBit-ChangeBit-EraseBytes-CrossOver-CrossOver-CopyPart-ShuffleBytes-ChangeByte-ChangeByte-CopyPart-CrossOver-CopyPart-CrossOver-CrossOver-EraseBytes-EraseBytes-ShuffleBytes-InsertRepeatedBytes-ChangeBit-CopyPart-Custom- DE: "\xfe\xff\xff\xfc"-"\x00\x00\x00\x00"-"F\x00"-"\xf3\xff\xff\xff"-"St9exception"-"_\x00\x00\x00"-"\xf6\xff\xff\xff"-"\xfe\xff\xff\xff"-"\x00\x00\x00\x00"-"p\x02\x00\x00\x00\x00\x00\x00"-"\xfe\xff\xff\xfb"-"\xff\xff"-"\xff\xff\xff\xff"-"\x01\x00\x00\x07"-"\xfe\xff\xff\xfe"-

These are prohibitively large and of limited value in the default case (when
someone is running the fuzzer, not debugging it), in my opinion.

[mhlakhani]

I am happy to move discussion on whether this patch is useful to the community to the mailing list, given the size of the patch I figured I would put it up directly for review over here.

Note that I don't have commit access to the repo, so I would need some help in getting this committed if the patch is acceptable.

[plotfi]

compiler-rt/lib/fuzzer/FuzzerLoop.cpp

40

Why 10?

639

const int maxLength = Options.Verbosity >= 2 ? -1 : kMaxMutationsToPrint;

643

Why not give PrintMutationSequence a default parameter?

compiler-rt/lib/fuzzer/FuzzerMutate.cpp

485

Any reason its int32_t and not just an int or a size_t? Seems like it should be a size_t.

489

How about

size_t entriesToPrint = maxLength ? std::min(maxLength, CurrentDictionaryEntrySequence.size()) : CurrentDictionaryEntrySequence.size();

494–497

How about

entriesToPrint = maxLength ? std::min(maxLength, CurrentDictionaryEntrySequence.size()) : CurrentDictionaryEntrySequence.size();

498

Why not keep the modern syntax and instead do:

for (auto DE : CurrentDictionaryEntrySequence) {
  if (!(--entriesToPrint))
    break;
  Printf("\"");
  PrintASCII(DE->GetW(), "\"-");
}

[mhlakhani]

compiler-rt/lib/fuzzer/FuzzerLoop.cpp

40

I'm looking for feedback on what a good value is. The resulting lines didn't seem too long with a value of 10, but this is a guess and not a perfect value.

643

This is done below, unless I am missing something?

compiler-rt/lib/fuzzer/FuzzerMutate.cpp

485

The only reason this is int32_t here is so we could use a default of -1 to indicate unlimited.

An alternative way to design this is to potentially move kMaxMutationsToPrint to be inside this file, and instead take a boolean argument that indicates whether we apply this limit or not. I'm happy to try out that version if preferable.

[morehouse]

Seems like a reasonable patch to me. Please address @plotfi's comments, then I'll take a closer look.

[mhlakhani]

address review comments

[mhlakhani]

most of the clang-tidy checks are pointing out issues in the existing code, or places where I am matching the style within libfuzzer's code. I hope it's OK to leave those unfixed.

[morehouse]

A test would be nice, but maybe tricky.

Maybe we could contrive a test like this:

• custom mutator that does nothing until the Xth run (X > 10), at which point it returns a hard-coded input that finds the bug
• run with -mutate_depth=100
• use grep to count the number of mutations output by the fuzzer

compiler-rt/lib/fuzzer/FuzzerMutate.cpp

487–491

Nit: Please capitalize local vars for consistency with existing style

498

I prefer the original syntax (straightforward index incrementing loop) since it is slightly more compact and requires slightly less thought to understand what its doing.

[mhlakhani]

Address review comments:

• Revert back to index based for loop
• Add a test for the behaviour

I couldn't figure out a way to grep exactly for the number of mutations but I think this is close enough.
The test sets up a mutator which calls LLVMFuzzerMutate a large number of times, which replicates
the behavior in my actual mutator.

I then added two test cases:

One that runs this with -verbosity=2 and verifies we see very long mutation sequences -
this identifies a mutation sequence by the presence of NEW: and checks via grep that a line
that is longer than 1kb exists. (i.e. producing the old behaviour, and verifying that verbose
data is still available)

The fix is verified by repeating the above test but without the -verbosity option, and verifying
that long lines are no longer seen (all lines are < 1kb).

I inspected the log files on my local machine as well and verified they look good

[morehouse]

compiler-rt/test/fuzzer/fuzzer-custommutator.test

22

No need to rebuild the test here.

[mhlakhani]

don't rebuild test binary twice

[mhlakhani]

thanks for all the feedback, @morehouse and @plotfi! With the latest change I believe all the comments are addressed.

I don't have commit privileges, so I would appreciate some help from either of you to commit this patch.

[morehouse]

Had to revert due to multiple buildbot failures:
http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux-fuzzer/builds/38581/steps/check-fuzzer/logs/stdio
http://green.lab.llvm.org/green//job/clang-stage1-RA/14180/consoleFull#-1417328700a1ca8a51-895e-46c6-af87-ce24fa4cd561

[mhlakhani]

apologies for the thrash here, the build bot failure is indeed confusing.

This is unfortunately one of those "works on my machine" cases -- looking at the logs it's not immediately obvious to me what the failure is. @morehouse , do you have suggestions on how I could go about debugging it?

[morehouse]

The log from the darwin bot has:

+ : 'RUN: at line 18'
+ grep NEW /Users/buildslave/jenkins/workspace/clang-stage1-RA/clang-build/tools/clang/runtime/compiler-rt-bins/test/fuzzer/X86_64DefaultDarwinConfig/Output/fuzzer-custommutator.test.tmp-mutate-verbose-log
+ grep '.\{1024\}'
grep: invalid repetition count(s)

So at least one issue seems to be from different grep feature support on different machines.

[mhlakhani]

Thanks! Will find a more portable solution for that. I'll also continue investigating the linux failure (http://lab.llvm.org:8011/builders/sanitizer-x86_64-linux-fuzzer/builds/38581/steps/check-fuzzer/logs/stdio) which seems to be a different issue. Is there a way to get access to the contents of /b/sanitizer-x86_64-linux-fuzzer/build/llvm_build0/projects/compiler-rt/test/fuzzer/X86_64DefaultLinuxConfig/Output/fuzzer-custommutator.test.tmp-mutate-log ?

[morehouse]

I do have access to that bot, but the log is gone already. Sorry.

[mhlakhani]

I think I've managed to reproduce that failure locally, working on a fix. Is there a way to kick off the failing tests before commit, so we can verify that they are all fixed before attempt to land this again?

[morehouse]

The libFuzzer tests automatically run on harbormaster when you update the patch, but that's often a different environment than the bots.

Unfortunately we have to push a commit before the bots will will catch any issues on their configs.

[mhlakhani]

Attempt to fix test failures.
Rewrite the test to be more portable by using awk for the line length check
and updating the grep statement as a result.

Tested on a linux machine using ninja check-fuzzer and on a mac
by copying over the log files and rerunning the awk+grep commands and
verifying exit codes

[mhlakhani]

These test failures are legitimate, will see if I can somehow get them to reproduce on my local environment (not sure how just yet ...)

[mhlakhani]

@morehouse I spent some more time digging and it's hard to get a portable test that works across machines, because I don't know how to express the condition I'm trying to check for within the test framework. Do you have any suggestions here?

Alternatively, how bad is it if we land this without a test?

[morehouse]

I'd like to keep the test, but we can separate it into its own file and use UNSUPPORTED or REQUIRES to avoid running on systems that don't have the tools we need.

Another idea: if we can express the length check using FileCheck regexes, we could use that instead of grep or awk and get portability automatically.

[mhlakhani]

Rewrite test

[mhlakhani]

I'm hopeful this should work. I wasn't able to find a portable way to assert on the full line length, but I found a seed where the verbose value is not prohibitively long, and the trimmed value is indeed a subset. It was possible to assert against the whole sequence this way.

This test should be stable across platforms assuming the RNG is portable (I hope...)

[mhlakhani]

Make test a bit more robust by also verifying the start of the range

[morehouse]

compiler-rt/test/fuzzer/fuzzer-custommutator.test

19

Unfortunately, RNG is not identical across platforms.

Rather than matching specific mutations, can you use a regex to match any 1024 characters on the same line?

[mhlakhani]

Rewrite test to be independent of the seed

I think I've finally got the syntax right after fighting with the escaping and the FileCheck docs.
This asserts that when verbosity=2, we get a line with >= 11 mutation sequences (letters separated by a dash), and with lower verbosity no such line is found

[mhlakhani]

fix comment

[morehouse]

Test looks good, thanks for figuring out the regex stuff.

[ldionne]

That's one hell of a commit message :-)

compiler-rt/lib/fuzzer/FuzzerLoop.cpp

 #if __has_feature(memory_sanitizer)
 #undef NO_SANITIZE_MEMORY
 #define NO_SANITIZE_MEMORY __attribute__((no_sanitize_memory))
 #endif
 #endif
 
 namespace fuzzer {
 static const size_t kMaxUnitSizeToPrint = 256;
 
 thread_local bool Fuzzer::IsMyThread;
 
 bool RunningUserCallback = false;
 
 // Only one Fuzzer per process.
 static Fuzzer *F;
 
 // Leak detection is expensive, so we first check if there were more mallocs

 }
 
 void Fuzzer::PrintStatusForNewUnit(const Unit &U, const char *Text) {
   if (!Options.PrintNEW)
     return;
   PrintStats(Text, "");
   if (Options.Verbosity) {
     Printf(" L: %zd/%zd ", U.size(), Corpus.MaxInputSize());
-    MD.PrintMutationSequence();
+    MD.PrintMutationSequence(Options.Verbosity >= 2);
     Printf("\n");
   }
 }
 
 void Fuzzer::ReportNewCoverage(InputInfo *II, const Unit &U) {
   II->NumSuccessfullMutations++;
   MD.RecordSuccessfulMutationSequence();
   PrintStatusForNewUnit(U, II->Reduced ? "REDUCE" : "NEW   ");
   WriteToOutputCorpus(U);
   NumberOfNewUnitsAdded++;
   CheckExitOnSrcPosOrItem(); // Check only after the unit is saved to corpus.
   LastCorpusUpdateRun = TotalNumberOfRuns;

compiler-rt/lib/fuzzer/FuzzerMutate.h

 namespace fuzzer {
 
 class MutationDispatcher {
 public:
   MutationDispatcher(Random &Rand, const FuzzingOptions &Options);
   ~MutationDispatcher() {}
   /// Indicate that we are about to start a new sequence of mutations.
   void StartMutationSequence();
-  /// Print the current sequence of mutations.
-  void PrintMutationSequence();
+  /// Print the current sequence of mutations. Only prints the full sequence
+  /// when Verbose is true.
+  void PrintMutationSequence(bool Verbose = true);
   /// Return the current sequence of mutations.
   std::string MutationSequence();
   /// Indicate that the current sequence of mutations was successful.
   void RecordSuccessfulMutationSequence();
   /// Mutates data by invoking user-provided mutator.
   size_t Mutate_Custom(uint8_t *Data, size_t Size, size_t MaxSize);
   /// Mutates data by invoking user-provided crossover.
   size_t Mutate_CustomCrossOver(uint8_t *Data, size_t Size, size_t MaxSize);

compiler-rt/lib/fuzzer/FuzzerMutate.cpp

 #include "FuzzerIO.h"
 #include "FuzzerMutate.h"
 #include "FuzzerOptions.h"
 #include "FuzzerTracePC.h"
 
 namespace fuzzer {
 
 const size_t Dictionary::kMaxDictSize;
+static const size_t kMaxMutationsToPrint = 10;
 
 static void PrintASCII(const Word &W, const char *PrintAfter) {
   PrintASCII(W.data(), W.size(), PrintAfter);
 }
 
 MutationDispatcher::MutationDispatcher(Random &Rand,
                                        const FuzzingOptions &Options)
     : Rand(Rand), Options(Options) {
for (auto &DE: V) {
     assert(DE.GetW().size());
     Printf("\"");
     PrintASCII(DE.GetW(), "\"");
     Printf(" # Uses: %zd\n", DE.GetUseCount());
   }
   Printf("###### End of recommended dictionary. ######\n");
 }
 
-void MutationDispatcher::PrintMutationSequence() {
+void MutationDispatcher::PrintMutationSequence(bool Verbose) {
   Printf("MS: %zd ", CurrentMutatorSequence.size());
-  for (auto M : CurrentMutatorSequence)
-    Printf("%s-", M.Name);
+  size_t EntriesToPrint =
+      Verbose ? CurrentMutatorSequence.size()
+              : std::min(kMaxMutationsToPrint, CurrentMutatorSequence.size());
+  for (size_t i = 0; i < EntriesToPrint; i++)
+    Printf("%s-", CurrentMutatorSequence[i].Name);
   if (!CurrentDictionaryEntrySequence.empty()) {
     Printf(" DE: ");
-    for (auto DE : CurrentDictionaryEntrySequence) {
+    EntriesToPrint = Verbose ? CurrentDictionaryEntrySequence.size()
+                             : std::min(kMaxMutationsToPrint,
+                                        CurrentDictionaryEntrySequence.size());
+    for (size_t i = 0; i < EntriesToPrint; i++) {
       Printf("\"");
-      PrintASCII(DE->GetW(), "\"-");
+      PrintASCII(CurrentDictionaryEntrySequence[i]->GetW(), "\"-");
     }
   }
 }
 
 std::string MutationDispatcher::MutationSequence() {
   std::string MS;
   for (auto M : CurrentMutatorSequence) {
     MS += M.Name;

compiler-rt/test/fuzzer/CustomMutatorWithLongSequencesTest.cpp

+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+
+// Simple test for a cutom mutator that results in long sequences of mutations.
+#include <assert.h>
+#include <cstddef>
+#include <cstdint>
+#include <cstdlib>
+#include <iostream>
+#include <ostream>
+
+#include "FuzzerInterface.h"
+
+static volatile int Sink;
+
+extern "C" int LLVMFuzzerTestOneInput(const uint8_t *Data, size_t Size) {
+  assert(Data);
+  if (Size > 0 && Data[0] == 'H') {
+    Sink = 1;
+    if (Size > 1 && Data[1] == 'i') {
+      Sink = 2;
+      if (Size > 2 && Data[2] == '!') {
+        std::cout << "BINGO; Found the target, exiting\n"
+                  << std::flush;
+        exit(1);
+      }
+    }
+  }
+  return 0;
+}
+
+extern "C" size_t LLVMFuzzerCustomMutator(uint8_t *Data, size_t Size,
+                                          size_t MaxSize, unsigned int Seed) {
+  // Run this 25 times to generate a large mutation sequence.
+  for (size_t i = 0; i < 25; i++) {
+    LLVMFuzzerMutate(Data, Size, MaxSize);
+  }
+  return LLVMFuzzerMutate(Data, Size, MaxSize);
+}

compiler-rt/test/fuzzer/fuzzer-custommutator.test

 RUN: %cpp_compiler %S/CustomMutatorTest.cpp -o %t-CustomMutatorTest
 RUN: not %run %t-CustomMutatorTest 2>&1 | FileCheck %s --check-prefix=LLVMFuzzerCustomMutator
 LLVMFuzzerCustomMutator: INFO: found LLVMFuzzerCustomMutator
 LLVMFuzzerCustomMutator: In LLVMFuzzerCustomMutator
 LLVMFuzzerCustomMutator: {{.*}} lim: 4096 {{.*}}
 LLVMFuzzerCustomMutator: BINGO
 
 # len_control is disabled for custom mutators by default, test that it can be enabled.
 RUN: not %run %t-CustomMutatorTest -len_control=1000 2>&1 | FileCheck %s --check-prefix=LLVMFuzzerCustomMutatorWithLenControl
 LLVMFuzzerCustomMutatorWithLenControl: INFO: found LLVMFuzzerCustomMutator
 LLVMFuzzerCustomMutatorWithLenControl: In LLVMFuzzerCustomMutator
 LLVMFuzzerCustomMutatorWithLenControl: {{.*}} lim: {{[1-9][0-9]?}} {{.*}}
 LLVMFuzzerCustomMutatorWithLenControl: BINGO
+
+# sanity check: verify that we do get long lines with verbose printing on
+RUN: %cpp_compiler %S/CustomMutatorWithLongSequencesTest.cpp -o %t-CustomMutatorWithLongSequencesTest
+RUN: not %run %t-CustomMutatorWithLongSequencesTest -verbosity=2 2>&1 | FileCheck %s --check-prefix=LLVMFuzzerCustomMutatorLongSequence
+LLVMFuzzerCustomMutatorLongSequence: Flag: verbosity 2
+LLVMFuzzerCustomMutatorLongSequence: {{.*}} MS: {{[0-9]*}} {{(([a-zA-Z]*-){11,})}} {{.*}}
+LLVMFuzzerCustomMutatorLongSequence: BINGO
+
+# check a target that prints long mutation sequences and verifies the printed
+# output is capped at 10 entries
+RUN: not %run %t-CustomMutatorWithLongSequencesTest 2>&1 | FileCheck %s --check-prefix=LLVMFuzzerCustomMutatorLongSequenceTrimmed
+LLVMFuzzerCustomMutatorLongSequenceTrimmed-NOT: Flag: verbosity 2
+LLVMFuzzerCustomMutatorLongSequenceTrimmed-NOT: {{.*}} MS: {{[0-9]*}} {{(([a-zA-Z]*-){11,})}} {{.*}}
+LLVMFuzzerCustomMutatorLongSequenceTrimmed: BINGO