Stuck at "Performing pilot run"

[floyd-fuh]

Hi there,

I seem to be stuck when trying to do a fuzzing run. My class to fuzz:

import java.io.ByteArrayInputStream;

import java.io.IOException;

import some.import.other.SomeParser;
import some.import.other.CustomExceptionOne;
import some.import.other.CustomExceptionTwo;

import org.junit.runner.RunWith;
import edu.berkeley.cs.jqf.fuzz.junit.Fuzz;
import edu.berkeley.cs.jqf.fuzz.junit.quickcheck.JQF;

@RunWith(JQF.class)
public class SilentDriver {
        @Fuzz
        public void main(byte[] arg) throws IOException, CustomExceptionOne, CustomExceptionTwo {
            SomeParser parser = new SomeParser();
            final ByteArrayInputStream stream = new ByteArrayInputStream(arg);
            parser.parse(stream);
            stream.close();
            parser.toString();
        }
}

How it gets stuck:

$ /opt/jqf/bin/jqf-afl-fuzz -c /opt/jqf/example/other/bin/:/opt/jqf/examples/target/classes/:/opt/jqf/examples/target/test-classes:/opt/jqf/fuzz/target/jqf-fuzz-1.0-SNAPSHOT.jar:/opt/jqf/examples/target/dependency/*:someCwdJar.jar -i in_dir/ -o out_dir/ SilentDriver main
Performing pilot run....

I know that the SomeParser isn't the fastest, so it might take a while (a second or two per invocation). However, it seems stuck.

afl-fuzz is by default very verbose and talks to me what it's trying to do, while jqf-afl-fuzz is very quiet. "Performing pilot run" doesn't mean anything to me. Can I enable logging? Can I run it verbosely? What is happening?

[floyd-fuh]

Ok, so it seems I wasn't patient enough... After 15 minutes the AFL screen popped up. But it doesn't really update at all:

                  american fuzzy lop 2.52b (SilentDriver#main)

┌─ process timing ─────────────────────────────────────┬─ overall results ─────┐
│        run time : 0 days, 0 hrs, 2 min, 27 sec       │  cycles done : 0      │
│   last new path : none seen yet                      │  total paths : 1      │
│ last uniq crash : none seen yet                      │ uniq crashes : 0      │
│  last uniq hang : none seen yet                      │   uniq hangs : 0      │
├─ cycle progress ────────────────────┬─ map coverage ─┴───────────────────────┤
│  now processing : 0 (0.00%)         │    map density : 0.00% / 0.00%         │
│ paths timed out : 0 (0.00%)         │ count coverage : 1.00 bits/tuple       │
├─ stage progress ────────────────────┼─ findings in depth ────────────────────┤
│  now trying : havoc                 │ favored paths : 1 (100.00%)            │
│ stage execs : 1/25 (4.00%)          │  new edges on : 1 (100.00%)            │
│ total execs : 11                    │ total crashes : 0 (0 unique)           │
│  exec speed : 3.26/sec (zzzz...)    │  total tmouts : 0 (0 unique)           │
├─ fuzzing strategy yields ───────────┴───────────────┬─ path geometry ────────┤
│   bit flips : n/a, n/a, n/a                         │    levels : 1          │
│  byte flips : n/a, n/a, n/a                         │   pending : 1          │
│ arithmetics : n/a, n/a, n/a                         │  pend fav : 1          │
│  known ints : n/a, n/a, n/a                         │ own finds : 0          │
│  dictionary : n/a, n/a, n/a                         │  imported : n/a        │
│       havoc : 0/0, 0/0                              │ stability : 100.00%    │
│        trim : 33.33%/1, n/a                         ├────────────────────────┘
└─────────────────────────────────────────────────────┘             [cpu: 48%]

I'm actually missing the -t flag, can I somehow specify the timeout it should use?

[floyd-fuh]

The GUI hasn't moved for half an hour.

I mean there will for sure be files that could DoS and hang the application, so I don't know how you tackle hangs, but this doesn't seem to work for me.

[rohanpadhye]

Hi Floyd,

You do not need to be so patient; something is definitely wrong. Typically, it takes like 1-2 seconds for the AFL screen to pop up on most benchmarks for me.

I'm not sure if this is related, but I pushed a change 3 days ago to prevent some issues with getting stuck for true random bytes from /dev/random. Please make sure you are on the latest commit.

As for verbosity, you can give the -v option to jqf-afl-fuzz and see the logging output from the JVM (instrumentation logging + STDOUT from your test classes) in the file jqf.log. I've documented this in the wiki now too; thanks for the feedback!

For debugging your issue I'd ask you to try two things:

1. Let me know if the bundled benchmark DateFormatterTest works for you. In bash:

/opt/jqf/bin/jqf-afl-fuzz -vc $(/opt/jqf/scripts/classpath.sh) edu.berkeley.cs.jqf.examples.jdk.DateFormatterTest fuzzSimple

Date-format fuzzing should run at anywhere between 500/sec to 4,000/sec depending on your hardware and OS. If you get "zzz" for this let me know.

2. If this works, but your example does not, I suspect it could be because JQF is generating ridiculously large inputs for you. Try limiting the size of the inputs using the Quickcheck annotation Size:

public void main(byte @Size(max=200)[] arg) throws IOException, CustomExceptionOne, CustomExceptionTwo {         
    /*.. or simply prevent the parser from reading more than X bytes some other way ..*/
}

If item 1 works but item 2 does not, then it could just be the parser taking a very long time to execute. JQF does not handle hangs at all at this point, which is a limitation (mainly because we are interested in unit tests and not long-running programs). I'm trying to find good ways to kill running threads preemptively without breaking too much (Thread.stop in the JDK is deprecated, and Future.cancel or Thread.interrupt leaks resources because the threads aren't actually killed). If you have any suggestions here, I would love to hear them!

[floyd-fuh]

Thanks for the detailed response! First of all the good news, I let the "stuck" fuzzer run for a couple of days and it seems to have worked kind of. Also the UI seems to update every other minute or so:

                  american fuzzy lop 2.52b (SilentDriver#main)

┌─ process timing ─────────────────────────────────────┬─ overall results ─────┐
│        run time : 4 days, 18 hrs, 26 min, 33 sec     │  cycles done : 3227   │
│   last new path : none yet (odd, check syntax!)      │  total paths : 1      │
│ last uniq crash : 4 days, 18 hrs, 10 min, 52 sec     │ uniq crashes : 2      │
│  last uniq hang : none seen yet                      │   uniq hangs : 0      │
├─ cycle progress ────────────────────┬─ map coverage ─┴───────────────────────┤
│  now processing : 0 (0.00%)         │    map density : 0.00% / 0.00%         │
│ paths timed out : 0 (0.00%)         │ count coverage : 1.00 bits/tuple       │
├─ stage progress ────────────────────┼─ findings in depth ────────────────────┤
│  now trying : havoc                 │ favored paths : 1 (100.00%)            │
│ stage execs : 24/25 (96.00%)        │  new edges on : 1 (100.00%)            │
│ total execs : 80.7k                 │ total crashes : 14.4k (2 unique)       │
│  exec speed : 3.29/sec (zzzz...)    │  total tmouts : 0 (0 unique)           │
├─ fuzzing strategy yields ───────────┴───────────────┬─ path geometry ────────┤
│   bit flips : n/a, n/a, n/a                         │    levels : 1          │
│  byte flips : n/a, n/a, n/a                         │   pending : 0          │
│ arithmetics : n/a, n/a, n/a                         │  pend fav : 0          │
│  known ints : n/a, n/a, n/a                         │ own finds : 0          │
│  dictionary : n/a, n/a, n/a                         │  imported : n/a        │
│       havoc : 2/80.7k, 0/0                          │ stability : 100.00%    │
│        trim : 33.33%/1, n/a                         ├────────────────────────┘
└─────────────────────────────────────────────────────┘             [cpu: 50%]

But something went wrong with the "paths", it doesn't seem to find any paths. Also, the crashes are not crashing the target, so it didn't work properly. I actually wonder where these crashes are coming from, maybe some high CPU load glitches.

Then another information I forgot to say: I'm running on ARM (odroid u3, quad core 1.7GHz with 2GB ram, CPU cores are idling before I start jqf). Although that shouldn't matter because we are fuzzing java and fuzz/src/main/c/afl-proxy.c seems to compile just fine. Let me know if anything else architecture dependent comes to mind.

I went on and git pulled your changes as you suggested and ran make and mvn package -DskipTests. Then I ran my fuzzing run again, but with -v argument. However, jqf was just stuck for several minutes and didn't write a jqf.log during that time, I searched everywhere for it :( . When I aborted I got:

Performing pilot run....^C  ERROR: Pilot run failed!!!
[JANALA] Instrumenting: java/util/regex/Pattern... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$4... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Node... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$LastNode... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$GroupHead... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Slice... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$SliceNode... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$BnM... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Start... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$TreeInfo... Done!
[JANALA] Instrumenting: java/util/regex/Matcher... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Single... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$BmpCharProperty... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$CharProperty... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Begin... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$First... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$SliceI... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$BranchConn... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Branch... Done!
[JANALA] Instrumenting: SilentDriver... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$GroupTail... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$BitClass... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Ctype... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$CharProperty$1... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$5... Done!
[JANALA] Instrumenting: java/util/regex/Pattern$Curly... Done!

So I ran the test you suggested:

$ date && /opt/jqf/bin/jqf-afl-fuzz -vc $(/opt/jqf/scripts/classpath.sh) edu.berkeley.cs.jqf.examples.jdk.DateFormatterTest fuzzSimple
Tue Feb 27 20:35:46 ACDT 2018
Performing pilot run....  Pilot run success! Launching AFL now...
afl-fuzz 2.52b by <lcamtuf@google.com>
[+] You have 4 CPU cores and 2 runnable tasks (utilization: 50%).
[+] Try parallel jobs - see /usr/local/share/doc/afl/parallel_fuzzing.txt.
[!] WARNING: Not binding to a CPU core (AFL_NO_AFFINITY set).
[*] Checking core_pattern...
[*] Checking CPU scaling governor...
[*] Setting up output directories...
[*] Scanning '/tmp/jqf-seeds.wsH'...
[+] No auto-generated dictionary tokens to reuse.
[*] Creating hard links for all input files...
[*] Validating target binary...
[*] Attempting dry run with 'id:000000,orig:random_seed_1'...
[*] Spinning up the fork server...
[+] All right - fork server is up.
    len = 1024, map size = 23, exec speed = 17615717 us
[*] Attempting dry run with 'id:000001,orig:random_seed_2'...
    len = 1024, map size = 54, exec speed = 271209 us
[!] WARNING: Instrumentation output varies across runs.
[*] Attempting dry run with 'id:000002,orig:random_seed_3'...
    len = 1024, map size = 32, exec speed = 203460 us
[*] Attempting dry run with 'id:000003,orig:random_seed_4'...
    len = 1024, map size = 26, exec speed = 200902 us
[*] Attempting dry run with 'id:000004,orig:random_seed_5'...
    len = 1024, map size = 54, exec speed = 208842 us
[+] All test cases processed.

[!] WARNING: The target binary is pretty slow! See /usr/local/share/doc/afl/perf_tips.txt.
[+] Here are some useful stats:

    Test case count : 3 favored, 1 variable, 5 total
       Bitmap range : 23 to 54 bits (average: 37.80 bits)
        Exec timing : 200k to 17.6M us (average: 2.18M us)

[*] No -t option specified, so I'll use exec timeout of 1000 ms.
[+] All set and ready to roll!


     american fuzzy lop 2.52b (edu.berkeley.cs.jqf.examples.jdk.DateFor...)

┌─ process timing ─────────────────────────────────────┬─ overall results ─────┐
│        run time : 0 days, 0 hrs, 2 min, 44 sec       │  cycles done : 0      │
│   last new path : none seen yet                      │  total paths : 5      │
│ last uniq crash : none seen yet                      │ uniq crashes : 0      │
│  last uniq hang : none seen yet                      │   uniq hangs : 0      │
├─ cycle progress ────────────────────┬─ map coverage ─┴───────────────────────┤
│  now processing : 2 (40.00%)        │    map density : 0.05% / 0.10%         │
│ paths timed out : 1 (20.00%)        │ count coverage : 1.35 bits/tuple       │
├─ stage progress ────────────────────┼─ findings in depth ────────────────────┤
│  now trying : trim 64/64            │ favored paths : 3 (60.00%)             │
│ stage execs : 9/16 (56.25%)         │  new edges on : 3 (60.00%)             │
│ total execs : 81                    │ total crashes : 0 (0 unique)           │
│  exec speed : 0.00/sec (zzzz...)    │  total tmouts : 0 (0 unique)           │
├─ fuzzing strategy yields ───────────┴───────────────┬─ path geometry ────────┤
│   bit flips : n/a, n/a, n/a                         │    levels : 1          │
│  byte flips : n/a, n/a, n/a                         │   pending : 5          │
│ arithmetics : n/a, n/a, n/a                         │  pend fav : 3          │
│  known ints : n/a, n/a, n/a                         │ own finds : 0          │
│  dictionary : n/a, n/a, n/a                         │  imported : n/a        │
│       havoc : 0/0, 0/0                              │ stability : 89.39%     │
│        trim : 56.25%/10, n/a                        ├────────────────────────┘
└─────────────────────────────────────────────────────┘             [cpu: 49%]

+++ Testing aborted by user +++
[+] We're done here. Have a nice day!
$ date
Tue Feb 27 20:41:03 ACDT 2018

Although it works it took about 6 minutes until the AFL UI came up (I stopped it right away when it came up). That's far away from the 1-2 seconds you have. I could imagine that it would take a couple of seconds more on an ARM, but 6 minutes is really surprising. I reran the tests to see how the AFL speed is and I got only about 4.00/sec.

At the moment I don't have a clue why the performance is so ridiculously bad, even when only one CPU core is used. Maybe the JVM ARM implementation is simply that bad. Maybe I'll try the Oracle JVM or so and I would let you know.

[floyd-fuh]

Just did a quick check and actually the DateFormatterTest and my target run just fine on my macbook, without any modifications. Ok, my target is still slow (around 5 execs/s), but it comes up really quickly. So it must be something on that ARM machine that makes it suuuper slow.

[rohanpadhye]

Ahh, thanks for the feedback. I do not have access to any ARM-based machines at this time (other than smartphones), so I have not tested JQF on that platform.

I don't think there is anything specifically in JQF that is x86-specific. As you mentioned, it is possibly the difference in the JVM implementation. JQF obviously performs lots of bytecode instrumentation, whose performance overheads can only be alleviated by an aggressively optimizing JIT compiler (e.g. HotSpot on x86). I do not know if the ARM-backend of HotSpot has some surprising gotchas.

[floyd-fuh]

Wow, ok, the problem is OpenJDK rather than ARM probably. Or a combination of OpenJDK+ARM. So basically I uninstalled OpenJDK and installed Oracle Java and it works fine on ARM! So the only things I tested so far:

Bad: ARM+OpenJDK
Good: ARM+Oracle Java
Good: non-ARM+Oracle Java

So maybe you want to write it in your documentation that Oracle Java should be used? Anyone successfully used OpenJDK on a regular x86 Linux before?

[floyd-fuh]

Ok so now that the performance problems are fixed, I still have the issue that it doesn't find any paths:

                  american fuzzy lop 2.52b (SilentDriver#main)

┌─ process timing ─────────────────────────────────────┬─ overall results ─────┐
│        run time : 0 days, 0 hrs, 17 min, 19 sec      │  cycles done : 595    │
│   last new path : none yet (odd, check syntax!)      │  total paths : 1      │
│ last uniq crash : 0 days, 0 hrs, 16 min, 36 sec      │ uniq crashes : 2      │
│  last uniq hang : none seen yet                      │   uniq hangs : 0      │
├─ cycle progress ────────────────────┬─ map coverage ─┴───────────────────────┤
│  now processing : 0 (0.00%)         │    map density : 0.00% / 0.00%         │
│ paths timed out : 0 (0.00%)         │ count coverage : 1.00 bits/tuple       │
├─ stage progress ────────────────────┼─ findings in depth ────────────────────┤
│  now trying : havoc                 │ favored paths : 1 (100.00%)            │
│ stage execs : 0/25 (0.00%)          │  new edges on : 1 (100.00%)            │
│ total execs : 14.9k                 │ total crashes : 1361 (2 unique)        │
│  exec speed : 3.73/sec (zzzz...)    │  total tmouts : 0 (0 unique)           │
├─ fuzzing strategy yields ───────────┴───────────────┬─ path geometry ────────┤
│   bit flips : n/a, n/a, n/a                         │    levels : 1          │
│  byte flips : n/a, n/a, n/a                         │   pending : 0          │
│ arithmetics : n/a, n/a, n/a                         │  pend fav : 0          │
│  known ints : n/a, n/a, n/a                         │ own finds : 0          │
│  dictionary : n/a, n/a, n/a                         │  imported : n/a        │
│       havoc : 2/14.9k, 0/0                          │ stability : 100.00%    │
│        trim : 33.33%/1, n/a                         ├────────────────────────┘
└─────────────────────────────────────────────────────┘             [cpu: 53%]

When I check jqf.log I only see hundreds of:

Exception in thread "Thread-442" java.lang.IllegalArgumentException: Invalid entry point: run
        at edu.berkeley.cs.jqf.instrument.tracing.ThreadTracer.<init>(ThreadTracer.java:82)
        at edu.berkeley.cs.jqf.instrument.tracing.ThreadTracer.spawn(ThreadTracer.java:103)
        at edu.berkeley.cs.jqf.instrument.tracing.TraceLogger.lambda$new$0(TraceLogger.java:39)
        at java.lang.ThreadLocal$SuppliedThreadLocal.initialValue(ThreadLocal.java:284)
        at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:180)
        at java.lang.ThreadLocal.get(ThreadLocal.java:170)
        at edu.berkeley.cs.jqf.instrument.tracing.TraceLogger.log(TraceLogger.java:43)
        at janala.logger.AbstractLogger.METHOD_BEGIN(AbstractLogger.java:698)
        at edu.berkeley.cs.jqf.instrument.tracing.SingleSnoop.METHOD_BEGIN(SingleSnoop.java:981)

I think my target is simply too complicated and something goes wrong in the instrumentation?

[rohanpadhye]

Hi Floyd.

Regarding performance: all my tests have been run on OpenJDK on Linux/x86 (which is also how we found bugs in OpenJDK 9). To augment your findings:

Bad: ARM+OpenJDK
Good: ARM+Oracle Java
Good: x86+Oracle Java
Good: x86+OpenJDK

So I guess the only bad combination that we know of is ARM/OpenJDK -- perhaps OpenJDK is not optimized for ARM? I know that Oracle Java uses basically the same source code as OpenJDK plus some OS/hardware-specific tweaks. Maybe that makes a much bigger difference on ARM. I'll try to look into this in more detail.

[rohanpadhye]

Regarding your other issue of no paths and invalid entry points, I believe the root cause is that your test program is multi-threaded. The exceptions you were seeing were a result of a bug in JQF for not correctly finding the Thread.run() entry point, which I have just fixed in commit 145de53. Sorry about that. Please try again with the latest version.

However, while my fix gets rid of the exceptions you were seeing and also instruments the child thread, there are some issues with using multi-threading and AFL that you should be aware of:

1. If you are starting new threads and not waiting for them to die before the end of a test method, then your tests may leak resources really quickly. If you do need to start auxiliary threads for some work, make sure to Thread.join() with them in a finally block before returning from your test method. This is standard JUnit testing advice.

2. JQF-AFL does not synchronize across threads. If you do not wait for threads to die before returning from the test method, you may see really low stability values in the AFL status screen, because the coverage from a child thread could show up in a subsequent run. Therefore, please make sure to complete all threads from a single run.

3. Exceptions thrown in child threads do not bubble up to the test method, and hence may not get reported to AFL as "crashes". If you are interested in looking for crashes, make sure that the test method would throw these exceptions as runtime exceptions that are not listed in the throws clause.

Some of my recent changes may also improve performance of multi-threaded targets a bit (due to removal of a volatile field), so let me know if you see better than "zzzz" for your fuzz target.

[floyd-fuh]

Ok, so I've pulled the changes and the Thread error messages are gone.

I'm actually fuzzing a Java library and only wrote the SilentDriver.java myself that is using the library. So I wasn't aware that the library was using multiple threads. So I could try to Thread.join but as I don't have a reference to the threads... I was hoping the library would clean up after itself.

The error I get now:

Time: 27.934
There were 7 failures:
1) main(SilentDriver)
java.lang.VerifyError: Stack map does not match the one at exception handler 71
Exception Details:
  Location:
    org/example.SomeClass.<init>()V @71: invokestatic
  Reason:
    Current frame's flags are not assignable to stack map frame's.
  Current Frame:
    bci: @37
    flags: { flagThisUninit }
    locals: { uninitializedThis }
    stack: { 'java/lang/Throwable' }
  Stackmap Frame:
    bci: @71
    flags: { }
    locals: { }
    stack: { 'java/lang/Throwable' }
  Bytecode:
    0x0000000: 1273 1274 1282 b800 7a2a bb00 0659 05b8
    0x0000010: 007e 12a9 12aa 1281 1274 1282 b800 86b7
    0x0000020: 0001 b800 8912 ab12 aa12 7312 7412 75b8
    0x0000030: 0086 b700 07a7 0007 b800 9dbf b800 8912
    0x0000040: ac12 adb8 00a3 b1b8 00a6 bf            
  Exception Handler Table:
    bci [50, 56] => handler: 56
    bci [37, 71] => handler: 71
  Stackmap Table:
    full_frame(@56,{},{Object[#168]})
    append_frame(@60,Object[#36])
    full_frame(@71,{},{Object[#168]})

        at SilentDriver.main(SilentDriver.java)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at edu.berkeley.cs.jqf.fuzz.junit.TrialRunner$1.evaluate(TrialRunner.java:58)
        at edu.berkeley.cs.jqf.fuzz.junit.TrialRunner.run(TrialRunner.java:64)
        at edu.berkeley.cs.jqf.fuzz.junit.quickcheck.FuzzStatement.evaluate(FuzzStatement.java:160)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
        at edu.berkeley.cs.jqf.fuzz.junit.GuidedFuzzing.run(GuidedFuzzing.java:144)
        at edu.berkeley.cs.jqf.fuzz.junit.GuidedFuzzing.run(GuidedFuzzing.java:90)
        at edu.berkeley.cs.jqf.fuzz.afl.AFLDriver.main(AFLDriver.java:58)
[...]
FAILURES!!!
Tests run: 1,  Failures: 15

About the performance: I don't think the speed is correct when the above problem occurs, but it seemed to be a little faster now (around 20 execs/s)

[rohanpadhye]

Good to know that the thread-running exceptions are gone. Did you see any increase in the number of paths after the last change?

Unfortunately, the final error you see appears to be an instrumentation issue that would be quite challenging for me to debug without access to the actual class file that caused it, but I'm sure that this is platform independent (i.e. that particular class file will reliably error out this way).

I haven't been able to reproduce that error with any of the libraries I've instrumented so far (such as subsets of OpenJDK, Apache Commons, Maven, Struts and Tomcat, among others). If you cannot share the class file for which this occurred, it may take some time before I can get to the bottom of this. I'll update this thread if I do manage to reproduce it (and hopefully fix it).

As always, thanks for your continued feedback!

[floyd-fuh]

Unfortunately I saw no new paths discovered after the last change.

The error that appears is probably the same as the Kelinci fuzzer had, as both your project and Kelinci use this org.objectweb.asm for instrumentation. There are certain limitations there, such as https://github.com/isstac/kelinci/blob/master/instrumentor/src/main/java/edu/cmu/sv/kelinci/instrumentor/Instrumentor.java#L67 and already discussed here as well: isstac/kelinci#2

Is there any possibility that you could catch instrumentation errors, warn the user that certain classes could not be instrumented, but then simply go on and use the non-instrumented classes?

The issue is I haven't done coordinated disclosure for various bugs I already found with Kelinci and therefore I would not like to disclose the target for now... and unfortunately I have another research project I have to do first... I hope you understand.

[floyd-fuh]

Ok, so here's the challenge for you I'm now able to disclose: Instrument tika-app.jar of the Apache Tika project https://tika.apache.org/

[rohanpadhye]

That's very useful info!

I'm testing a driver with the Tika.parse(InputStream) method and can see all the issues you were facing.

It's a very interesting benchmark because there are 3 distinct problems which I have not encountered in any other target so far:

1. TIKA spawns a child thread to parse inputs, but this thread is created with new Thread(Runnable) instead of sub-classing java.lang.Thread and overriding run(); JQF only used to handle the latter case. I have added support for the former case now, which was an easy fix. This was why you could not see any new paths. Most of the logic was in a child thread that was not being tracked. JQF avoids tracking threads unless they are known to be test program threads; this is to avoid slowdown due to instrumenting the JVM's own activity.

2. The VerifyError was caused due to a tricky case of a class calling a super-class constructor in a constructor before the call to super(). See VerifyError when new instance of superclass is created inside own constructor before super() or this() #22 for more details. I have addressed this as well, though undoubtedly it is a very hacky patch that is sure to cause more problems down the road :-\

3. The slow start-up and low "Stability" numbers in AFL's status screen are due to the fact that TIKA loads many classes which perform static class initialization. This code is only executed once, the first time the classes are loaded. Therefore, AFL sees it as non-reproducible code coverage. There is really nothing we can do about it other than not worry about the low stability numbers.

I've added the TIKA parser benchmark to the JQF repository, and I can see steady progress in the coverage and number of paths when using AFL's bundled seeds of all formats:

     american fuzzy lop 2.52b (edu.berkeley.cs.jqf.examples.tika.TikaPa...)

┌─ process timing ─────────────────────────────────────┬─ overall results ─────┐
│        run time : 0 days, 0 hrs, 12 min, 6 sec       │  cycles done : 0      │
│   last new path : 0 days, 0 hrs, 0 min, 0 sec        │  total paths : 719    │
│ last uniq crash : none seen yet                      │ uniq crashes : 0      │
│  last uniq hang : none seen yet                      │   uniq hangs : 0      │
├─ cycle progress ────────────────────┬─ map coverage ─┴───────────────────────┤
│  now processing : 14 (1.95%)        │    map density : 2.69% / 8.94%         │
│ paths timed out : 0 (0.00%)         │ count coverage : 2.39 bits/tuple       │
├─ stage progress ────────────────────┼─ findings in depth ────────────────────┤
│  now trying : calibration           │ favored paths : 149 (20.72%)           │
│ stage execs : 6/8 (75.00%)          │  new edges on : 228 (31.71%)           │
│ total execs : 25.0k                 │ total crashes : 0 (0 unique)           │
│  exec speed : 30.92/sec (slow!)     │  total tmouts : 0 (0 unique)           │
├─ fuzzing strategy yields ───────────┴───────────────┬─ path geometry ────────┤
│   bit flips : n/a, n/a, n/a                         │    levels : 2          │
│  byte flips : n/a, n/a, n/a                         │   pending : 709        │
│ arithmetics : n/a, n/a, n/a                         │  pend fav : 145        │
│  known ints : n/a, n/a, n/a                         │ own finds : 695        │
│  dictionary : n/a, n/a, n/a                         │  imported : n/a        │
│       havoc : 339/9266, 208/7264                    │ stability : 67.73%     │
│        trim : 6.77%/1595, n/a                       ├────────────────────────┘
└─────────────────────────────────────────────────────┘             [cpu:  9%]

The above can be run with the following BASH command:

 ./bin/jqf-afl-fuzz -i examples/src/test/seeds/afl-all-testcases/ -v -c $(./scripts/examples_classpath.sh) edu.berkeley.cs.jqf.examples.tika.TikaParserTest fuzz

It's still quite slow, but that's to be expected from a large code-base such as TIKA.

Thanks for helping me find so many bugs! If you don't mind I'd like to add you to the list of contributors for the project :-)

[floyd-fuh]

Thanks for the response and the amazing fast bug fixes!

I'm running the benchmark test you added and it works! But it is even much slower on my older ARM boxes (1.26/sec). I'm currently running the benchmark, but with a much larger corpus.

Oh btw. if you are interested what was found with Kelinci for Tika 1.17, this should be feasible for JQF to find if it would use Tika 1.17:
https://issues.apache.org/jira/browse/PDFBOX-4193
https://issues.apache.org/jira/browse/COMPRESS-447
Gagravarr/VorbisJava#27
https://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2018-1338
https://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2018-1339

Thanks for including me in the contributors, of course I don't mind.

I opened a couple of other issues for things I would like to discuss, but I think it is time now to close this issue as you managed to get Tika working, thanks for that again.