exec/s eventually goes to 0, jsfuzz seems to stop working

[humphd]

Really cool tool! I tried it out on a few libs today, and in one case the test run eventually just seemed to stop doing anything. It looks like jsfuzz is still working, but doing nothing (exec/s goes to 0 and stays there). Am I doing something wrong here, or is jsfuzz?

Here's my test case for the rss-parser module:

const Parser = require('rss-parser');
const parser = new Parser();

async function fuzz(buf) {
    try {
      await parser.parseString(buf);
    } catch (e) {
      if (
        e.message.indexOf('Non-whitespace before first tag') !== -1 ||
        e.message.indexOf('Unable to parse XML') !== 1
      ) {
        // ignore
      } else {
        throw e;
      }
    }
}

module.exports = {
    fuzz
};

And here's what I see when I run it. It just keeps going forever on #56120 PULSE cov: 2618 corp: 55 exec/s: 0.

> rss-parser-fuzz@1.0.0 test /private/tmp/rss-parser-fuzz
> jsfuzz fuzz.js

#0 READ units: 0
#0 PULSE     cov: 0 corp: 0 exec/s: 0 rss: 29.72 MB
#1 NEW     cov: 1958 corp: 0 exec/s: 3 rss: 172.35 MB
#2 NEW     cov: 2001 corp: 1 exec/s: 142 rss: 172.37 MB
#8 NEW     cov: 2005 corp: 2 exec/s: 375 rss: 172.37 MB
#12 NEW     cov: 2030 corp: 3 exec/s: 1000 rss: 172.37 MB
#16 NEW     cov: 2053 corp: 4 exec/s: 1000 rss: 172.37 MB
#32 NEW     cov: 2066 corp: 5 exec/s: 888 rss: 172.43 MB
#99 NEW     cov: 2091 corp: 6 exec/s: 848 rss: 175.77 MB
#110 NEW     cov: 2207 corp: 7 exec/s: 647 rss: 176.34 MB
#156 NEW     cov: 2228 corp: 8 exec/s: 754 rss: 176.85 MB
#162 NEW     cov: 2256 corp: 9 exec/s: 857 rss: 177.39 MB
#194 NEW     cov: 2260 corp: 10 exec/s: 1000 rss: 177.39 MB
#206 NEW     cov: 2261 corp: 11 exec/s: 857 rss: 177.39 MB
#246 NEW     cov: 2269 corp: 12 exec/s: 1025 rss: 177.39 MB
#283 NEW     cov: 2270 corp: 13 exec/s: 973 rss: 177.39 MB
#330 NEW     cov: 2274 corp: 14 exec/s: 1000 rss: 177.39 MB
#416 NEW     cov: 2276 corp: 15 exec/s: 1088 rss: 177.51 MB
#446 NEW     cov: 2279 corp: 16 exec/s: 1000 rss: 177.51 MB
#506 NEW     cov: 2376 corp: 17 exec/s: 1000 rss: 177.53 MB
#557 NEW     cov: 2378 corp: 18 exec/s: 1000 rss: 177.55 MB
#817 NEW     cov: 2423 corp: 19 exec/s: 866 rss: 177.97 MB
#913 NEW     cov: 2426 corp: 20 exec/s: 932 rss: 178.77 MB
#915 NEW     cov: 2432 corp: 21 exec/s: 1000 rss: 178.77 MB
#1020 NEW     cov: 2435 corp: 22 exec/s: 981 rss: 178.78 MB
#1195 NEW     cov: 2450 corp: 23 exec/s: 862 rss: 178.97 MB
#1275 NEW     cov: 2452 corp: 24 exec/s: 792 rss: 179.58 MB
#1331 NEW     cov: 2454 corp: 25 exec/s: 1018 rss: 179.99 MB
#1375 NEW     cov: 2456 corp: 26 exec/s: 956 rss: 180.34 MB
#1434 NEW     cov: 2458 corp: 27 exec/s: 766 rss: 180.84 MB
#1494 NEW     cov: 2460 corp: 28 exec/s: 800 rss: 180.85 MB
#1590 NEW     cov: 2462 corp: 29 exec/s: 793 rss: 180.9 MB
#1706 NEW     cov: 2484 corp: 30 exec/s: 748 rss: 180.92 MB
#1871 NEW     cov: 2500 corp: 31 exec/s: 833 rss: 180.92 MB
#1903 NEW     cov: 2503 corp: 32 exec/s: 711 rss: 180.93 MB
#1919 NEW     cov: 2507 corp: 33 exec/s: 842 rss: 180.93 MB
#2149 NEW     cov: 2517 corp: 34 exec/s: 725 rss: 181.01 MB
#2181 NEW     cov: 2520 corp: 35 exec/s: 727 rss: 181.01 MB
#2252 PULSE     cov: 2520 corp: 36 exec/s: 710 rss: 181.01 MB
#2263 NEW     cov: 2522 corp: 36 exec/s: 523 rss: 191.79 MB
#2723 NEW     cov: 2523 corp: 37 exec/s: 731 rss: 191.83 MB
#2730 NEW     cov: 2524 corp: 38 exec/s: 583 rss: 191.83 MB
#2786 NEW     cov: 2543 corp: 39 exec/s: 811 rss: 191.84 MB
#3274 NEW     cov: 2547 corp: 40 exec/s: 770 rss: 192 MB
#3803 NEW     cov: 2555 corp: 41 exec/s: 776 rss: 192.09 MB
#4040 NEW     cov: 2557 corp: 42 exec/s: 690 rss: 192.3 MB
#4481 PULSE     cov: 2557 corp: 43 exec/s: 720 rss: 192.3 MB
#4660 NEW     cov: 2559 corp: 43 exec/s: 821 rss: 192.38 MB
#5817 NEW     cov: 2561 corp: 44 exec/s: 756 rss: 192.46 MB
#5871 NEW     cov: 2570 corp: 45 exec/s: 620 rss: 192.46 MB
#6547 NEW     cov: 2576 corp: 46 exec/s: 752 rss: 192.55 MB
#6713 PULSE     cov: 2576 corp: 47 exec/s: 619 rss: 192.55 MB
#8187 NEW     cov: 2582 corp: 47 exec/s: 810 rss: 195.6 MB
#8473 NEW     cov: 2585 corp: 48 exec/s: 711 rss: 195.6 MB
#9061 NEW     cov: 2587 corp: 49 exec/s: 824 rss: 195.6 MB
#9111 PULSE     cov: 2587 corp: 50 exec/s: 746 rss: 195.64 MB
#11501 PULSE     cov: 2587 corp: 50 exec/s: 796 rss: 197.14 MB
#13904 PULSE     cov: 2587 corp: 50 exec/s: 801 rss: 198.03 MB
#16326 PULSE     cov: 2587 corp: 50 exec/s: 807 rss: 198.68 MB
#18779 PULSE     cov: 2587 corp: 50 exec/s: 817 rss: 199.6 MB
#21223 PULSE     cov: 2587 corp: 50 exec/s: 814 rss: 203.31 MB
#23665 PULSE     cov: 2587 corp: 50 exec/s: 814 rss: 207.01 MB
#25519 NEW     cov: 2608 corp: 50 exec/s: 806 rss: 213.17 MB
#26059 PULSE     cov: 2608 corp: 51 exec/s: 769 rss: 213.17 MB
#28444 PULSE     cov: 2608 corp: 51 exec/s: 794 rss: 176.61 MB
#30897 PULSE     cov: 2608 corp: 51 exec/s: 817 rss: 146.25 MB
#32817 NEW     cov: 2610 corp: 51 exec/s: 804 rss: 146.25 MB
#33284 PULSE     cov: 2610 corp: 52 exec/s: 760 rss: 146.28 MB
#35632 NEW     cov: 2614 corp: 52 exec/s: 806 rss: 141.19 MB
#35689 PULSE     cov: 2614 corp: 53 exec/s: 640 rss: 141.19 MB
#36302 NEW     cov: 2616 corp: 53 exec/s: 799 rss: 141.02 MB
#38021 PULSE     cov: 2616 corp: 54 exec/s: 769 rss: 141.03 MB
#40329 PULSE     cov: 2616 corp: 54 exec/s: 769 rss: 140.35 MB
#42614 PULSE     cov: 2616 corp: 54 exec/s: 761 rss: 140.46 MB
#45047 PULSE     cov: 2616 corp: 54 exec/s: 811 rss: 140.56 MB
#47468 PULSE     cov: 2616 corp: 54 exec/s: 807 rss: 138.84 MB
#49899 PULSE     cov: 2616 corp: 54 exec/s: 810 rss: 137.63 MB
#52311 PULSE     cov: 2616 corp: 54 exec/s: 804 rss: 136.08 MB
#54689 PULSE     cov: 2616 corp: 54 exec/s: 792 rss: 135.11 MB
#56120 NEW     cov: 2618 corp: 54 exec/s: 840 rss: 131.97 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 131.97 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 132.05 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 132.05 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 132.05 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 132.05 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 127.02 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.76 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.77 MB
#56120 PULSE     cov: 2618 corp: 55 exec/s: 0 rss: 122.64 MB
...

It goes on like that forever. I tried killing it, and restarting, and it happens again, just in a different spot:

...
#88029 NEW     cov: 2614 corp: 57 exec/s: 719 rss: 141.23 MB
#88842 PULSE     cov: 2614 corp: 58 exec/s: 689 rss: 141.23 MB
#90975 PULSE     cov: 2614 corp: 58 exec/s: 711 rss: 140.23 MB
#93196 PULSE     cov: 2614 corp: 58 exec/s: 740 rss: 135.98 MB
#95483 PULSE     cov: 2614 corp: 58 exec/s: 762 rss: 136.55 MB
#97647 PULSE     cov: 2614 corp: 58 exec/s: 721 rss: 136.71 MB
#99854 PULSE     cov: 2614 corp: 58 exec/s: 735 rss: 136.55 MB
#101142 NEW     cov: 2619 corp: 58 exec/s: 724 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
#101142 PULSE     cov: 2619 corp: 59 exec/s: 0 rss: 137.1 MB
...

A third run seems to go on fine for as long as I'm willing to wait, so it's not guaranteed to happen.

[yevgenypats]

@humphd Thanks for trying out! Looks like you found a DoS/Infinite loop pretty quickly as well as a bug in the timeout detector which is fixed now. It should report&save the crash/testcase when you rerun this with v1.0.5.

[yevgenypats]

@humphd I'll appreciate if you can add a link to the bug/bugfix in the trophies:) https://github.com/fuzzitdev/jsfuzz#trophies

[humphd]

Great, thanks @yevgenypats for pushing a fix.

I've updated to v1.0.5 and am seeing the following:

...
#850174 PULSE     cov: 2623 corp: 60 exec/s: 745 rss: 132 MB
#852349 PULSE     cov: 2623 corp: 60 exec/s: 725 rss: 133.95 MB
#854500 PULSE     cov: 2623 corp: 60 exec/s: 716 rss: 130.57 MB
#856413 NEW     cov: 2625 corp: 60 exec/s: 732 rss: 132.38 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 132.38 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
#856413 PULSE     cov: 2625 corp: 61 exec/s: 0 rss: 130.78 MB
=================================================================
timeout reached. testcase took: 30429
Worker killed
crash was written to crash-62d71e41452b1f8d3bc1882a235a5dbd3e2a930f213f85dbcb6d1bcb1663de29
crash(hex)=549bafff70c3ffff0000800593e7f5077ffffffff1640445b630727400c5624186050d5873e77fe1054186c5800445b6377274002000000186050d581d92faff053ce7f5077fff5873e77fe10541ff203e03643e000000001e10b8ec7fe7f50772f0e32021fa3401d32c00c57f4186050d581dff2c

I've been able to hit this a number of times, and when I try the test cases saved to the crash files, I get an expected exception error. That is, it seems like it's failing as it should:

(node:12276) UnhandledPromiseRejectionWarning: Error: Non-whitespace before first tag.
Line: 0
Column: 1
Char: �
    at error (/private/tmp/rss-parser-fuzz/node_modules/sax/lib/sax.js:651:10)
    at strictFail (/private/tmp/rss-parser-fuzz/node_modules/sax/lib/sax.js:677:7)
    at beginWhiteSpace (/private/tmp/rss-parser-fuzz/node_modules/sax/lib/sax.js:951:7)
    at SAXParser.write (/private/tmp/rss-parser-fuzz/node_modules/sax/lib/sax.js:1006:11)
    at Parser.exports.Parser.Parser.parseString (/private/tmp/rss-parser-fuzz/node_modules/xml2js/lib/parser.js:325:31)
    at Parser.parseString (/private/tmp/rss-parser-fuzz/node_modules/xml2js/lib/parser.js:5:59)
    at Promise (/private/tmp/rss-parser-fuzz/node_modules/rss-parser/lib/parser.js:32:22)
    at new Promise (<anonymous>)
    at Parser.parseString (/private/tmp/rss-parser-fuzz/node_modules/rss-parser/lib/parser.js:31:16)
    at fs.readFile (/private/tmp/rss-parser-fuzz/crash.js:12:16)
(node:12276) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
(node:12276) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

I'm not sure how to interpret this, and whether or not to pursue it further. I'm starting to wonder if the problem is in how I wrote the test case for jsfuzz: specifically how I reuse the parser instance over and over. Maybe there is some accumulated state that (eventually) causes problems.

I've currently trying two other cases that eliminate that problem (i.e., create a parser per run of the fuzz test), and both have been working fine for quite a while. I'll keep them going, but wanted to get your take on this.

[yevgenypats]

@humphd I think you are correct ( I didn't notice that you reuse the fuzzer), looks like the accumulated is causing the problem. It is best to start from a clean state for each run otherwise it will be hard to triage and understand which test-case cause the problem.