Solidity-coverage: Unresponsive with 100% CPU

[mikeshultz]

I was trying out solidity-coverage today but running into issues testing it out. I have ~17 contracts, and after "Instrumenting..." the process pegs one CPU core at 100% and never seems to finish(waited a bit over 1 hour).

How can I go about debugging this? I've tried the traditional node DEBUG env var with no useful output.

DEBUG="*" ./node_modules/.bin/solidity-coverage

Here's my .solcover.js file. I have tried without specifying port, testCommand, and norpc as well(also, ganache appears to not receive any transactions during this process).

module.exports = {
    port: 8545,
    testCommand: './node_modules/.bin/truffle test --network dev',
    norpc: true,
    copyNodeModules: true,
    skipFiles: ['Test.sol']
};

The process can not be terminated through a keyboard interrupt(ctrl+c) either. I'm running this on an Arch Linux system, if that helps. Let me know if I can provide any more information.

[cgewecke]

@mikeshultz Apologies, copyNodeModules is awful if you have a big node_modules. Can you try the copyPackages instead, just picking out the things you need?

I'm putting a more emphatic warning in the README right now.

[cgewecke]

To clarify - you only need to copy packages consumed by solidity files as imports (like Zeppelin). Truffle should resolve all other dependencies, correctly.

[mikeshultz]

@cgewecke Sorry, I should have mentioned this in my original post. This occurs even if copyNodeModules is false or undefined.

[cgewecke]

@mikeshultz Is your project public? Will take a look at it if so.

Another tool that's helpful with hangs is wtfnode. You run your command with it, let things hang for a while and ctrl-c out. It tells you what resources are being used.

[mikeshultz]

I'm not allowed share it at this time, no. wtfnode won't provide any information for this process, sadly, so that's no help. If I strace the process, it looks like the last instruction is to open one of the contract files(that probably should be of no concern to solidity-coverage since it's outside of the contracts directory.

getcwd("/home/mike/dev/contracts-project", 4096) = 31
openat(AT_FDCWD, "/home/mike/dev/contracts-project/coverageEnv/nocompile/Randumb.sol", O_RDONLY|O_CLOEXEC) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=570, ...}) = 0
read(12, "pragma solidity ^0.4.13;\n\n// Bad"..., 570) = 570
close(12)

Then it seems to get stuck in an infinite loop with these instructions:

getpid()                                = 16575
futex(0x33e3f94, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f40, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x3423190, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f94, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f40, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x3423190, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f94, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f40, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x3423190, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x33e3f90, FUTEX_WAKE_PRIVATE, 1) = 1
write(8, "\1\0\0\0\0\0\0\0", 8)         = 8

Let me know if I can provide any more info.

[cgewecke]

Oh there's a couple things aren't totally clear to me:

• Is your hang during instrumentation?
• Do any files instrument?
• Do all files instrument and then it hangs?

If you're getting part way through, could you try adding the file it hangs on to the skipFiles option in .solcover.js and see you get a complete run? That would isolate the problem a little.

[mikeshultz]

Is your hang during instrumentation?

That's unclear. It's been a while since I setup solidity-coverage, so I don't even remember what comes after instrumentation. It's possible it's just after instrumentation, but I can't tell for sure.

Do any files instrument?

Going by the stdout, yes.

Do all files instrument and then it hangs?

It looks like it's all of them(minus the ones skipped from .solcov.js).

If you're getting part way through, could you try adding the file it hangs on to the skipFiles option in .solcover.js and see you get a complete run? That would isolate the problem a little.

The final output I get is a skip, so I'm assuming it isn't hanging on a specific file: Skipping instrumentation of ./coverageEnv/contracts/Test.sol

To drive at what you seem to be getting at, I've modified exec.js to look like this:

app.generateCoverageEnvironment();
console.log('==========instrumentation begins==========');
app.instrumentTarget();
console.log('==========instrumentation complete==========');
app.launchTestrpc()
  .then(() => {
    app.runTestCommand();
    app.generateReport();
  })
  .catch(err => log(err));

I get the "begins" message, but not the "complete" one. So it must be stuck in instrumentation somewhere, even though it seems complete going by the script's stdout.

We have a handful of contracts in directories other than contracts, and that strace posted before seems like it might be reaching into them. If that's the case, truffle doesn't touch those and some might even be outright broken. If solidity-coverage doesn't concern itself specifically with the contracts directory in coverageEnv, should I try ignoring those other directories in .solcov.js?

[mikeshultz]

Also, I've tried adding every contract to skipFiles except one(SafeMath.sol) and the behavior still seems to occur.

[cgewecke]

@mikeshultz What happens if you temporarily remove the noCompile folder from the project? I think it must be hanging somewhere in here where SC sweeps across all the solidity files in a project and tries to rewrite the visibility modifiers of anything that might be imported into contracts.

[mikeshultz]

I think you hit the nail on the head. Moving that directory allowed the script to progress further. Though I can't do this permanently since these files still need to be in the repos for reference. Suggestions?

[cgewecke]

My preference is definitely to figure out what in that folder is causing the spin and fix the bug (in solidity-coverage). If any of that code becomes share-able or you can make a reproduction case please LMK.

[mikeshultz]

I was able to narrow it down to a concept test contract we were fooling around with. Was able to get permission to share it and I created a test case you can try out.

https://github.com/mikeshultz/solidity-coverage-randumb

Thankfully in this case I can just kill this contract in the original repo, but I hope it helps. Let me know if you want anything else.

[cgewecke]

@mikeshultz Awesome! Thank you.

[simondlr]

fwiw. I ran into this issue too. I have a more complicated setup however, requiring other components. Testing coverage on an oracle using Oraclize, so have to run a bridge too.

You can see it just hanging. This happened on my local machine too. Not sure how useful it is given its complexity.

https://circleci.com/gh/UjoTeam/contracts-oracle/7

[cgewecke]

@simondlr Peeked at this - it looks like it's having a problem with utils/UsingOraclize.sol. Even though you skip it, the tool still goes into that file to try to modify its ABI and is hitting an infinite loop while parsing something. . .

Will add these cases to our test suite and figure out what's going wrong here.

[cgewecke]

This issue looks like it might get a GitCoin bounty. Very exciting. Thank you @vs77bb!

To whomever is interested in working on it - I think this may be an infinite loop in preprocessor.js for some uncommon Solidity constructions. You might also just try running the failing Solidity examples above through the instrumenter function and seeing if that works / fails. There are lots of fixtures and examples in the test suite to help you pull out specific parts of the coverage tool to target for inspection. For example instrumentation can be investigated like this.

Thank you in advance anyone who'd like to take this on.

@mikeshultz Has a simple reproduction case above you could use to identify the source of the problem - but would also like to verify that we can instrument the Oraclize contract as well.

Bounty is 200 Dai for a diagnosis. 200 additional Dai for a fix (with unit test, sorry).

[gitcoinbot]

Issue Status: 1. Open 2. Started 3. Submitted 4. Done

---

__This issue now has a funding of 400.0 DAI (400.0 USD @ $1.0/DAI) attached to it.__

• If you would like to work on this issue you can 'start work' on the Gitcoin Issue Details page.
• Questions? Checkout Gitcoin Help or the Gitcoin Slack
• $16,401.51 more funded OSS Work available on the Gitcoin Issue Explorer

[h3ph4est7s]

The exclusion issue arrise when the line
https://github.com/sc-forks/solidity-coverage/blob/a40ba7b1b4c4fe03352eb4899aa27931a6734f6b/lib/app.js#L390
in postProcessPure does not properly check for excluded files. #259 is addressing this issue by adding an exclusion file/folder check.
As for the bug itself the process "hangs" (in the matter of fact is working) because of the unbracketed singleton statement parser at
https://github.com/sc-forks/solidity-coverage/blob/a40ba7b1b4c4fe03352eb4899aa27931a6734f6b/lib/preprocessor.js#L40
is too slow when it comes to parsing large contracts the main issue is the loop using:
https://github.com/sc-forks/solidity-coverage/blob/a40ba7b1b4c4fe03352eb4899aa27931a6734f6b/lib/preprocessor.js#L45
witch takes a lot of time to parse all the contract in every pass.
The aforementioned claim can be verified by applying the following patch:

--- lib/preprocessor.js (revision a40ba7b1b4c4fe03352eb4899aa27931a6734f6b)
+++ lib/preprocessor.js (date 1531305439000)
@@ -42,7 +42,10 @@

   while (keepRunning) {
     try {
+      console.time('parse');
       const ast = SolidityParser.parse(contract);
+      console.log('length: ' + contract.length);
+      console.timeEnd('parse');
       keepRunning = false;
       SolExplore.traverse(ast, {
         enter(node, parent) { // eslint-disable-line no-loop-func
@@ -84,6 +87,7 @@
         },
       });
     } catch (err) {
+      console.log(err);
       contract = err;
       keepRunning = false;
     }

and getting this output:

length: 46508
parse: 41473.762ms
length: 46500
parse: 41236.352ms
length: 46502
parse: 43498.465ms
length: 46504
parse: 41831.958ms
length: 46506
parse: 40028.604ms

and after approx. 40 * 40 / 60 = 26,66 minutes later

length: 46544
parse: 38760.110ms
length: 46540
parse: 41115.355ms
length: 46542
parse: 38606.990ms
length: 46544
parse: 36695.497ms
length: 46546
parse: 47062.380ms

this indicates that every iteration take approximately 40 seconds (in my machine), multiply that with the number of required passes and the result is really time consuming.

The conditions are triggered when using
usingOraclize.sol (SHA256: 79283d8e5f4f30fe33c6b0ab2296531bdd159f19438ec18fe9ebae2a5bc7edae)
file at:
https://github.com/sc-forks/solidity-coverage/blob/a40ba7b1b4c4fe03352eb4899aa27931a6734f6b/lib/app.js#L393

[cgewecke]

Ok excellent @h3ph4est7s, thanks so much. That definitely satisfies the diagnosis part of this bounty in my view. PR looks reasonable as well although it would be nice if there was a less awful algorithm in the pre-processor (I wrote it).

Also @h3ph4est7s to be clear - you and @mttmartin are different people?

[mttmartin]

Hi @cgewecke, yes, we are different people.

[vs77bb]

Hi @h3ph4est7s would you mind claiming this on Gitcoin here? @mttmartin has kindly agreed to give up his 'Start Work' here as he hadn't gotten going quite yet. We can add you from the wait list once you start work.

[h3ph4est7s]

Hi @vs77bb the project type is Traditional so its 1 worker at a time i cannot participate if there is a way that i don't currently know please inform me 😄. Also i wanted to clarify that i already have the diagnosis due to a project im working on and using oraclize service with solidity-coverage and i wasn't targeting on the bounty in the first place (it came out as a bonus) also i want to apologize to @mttmartin for the highjack.

[vs77bb]

@h3ph4est7s you should be good to go now! Please try again. Thanks for the clarification as well, this is a learning for us as a Gitcoin platform as you clearly had context coming in which made it easier for this issue to be solved - which ultimately is our goal. It'll be important for Gitcoin to keep this in consideration and account for it as the platform grows.

[cgewecke]

@h3ph4est7s Out of curiosity, with the fix in #259 are you able to get coverage working for contracts using Oraclize? e.g. there are no additional issues with bridge etc?

[cgewecke]

Also not sure this is within the scope of the bounty since skipping is an effective workaround for both the cases mentioned in the issue, but as a note to self, it's possible we should:

• break out the pure and view part of the pre-processor into its own method.
• Run across the AST for that case a single time, substituting a unique marker for the modifiers we want to remove. The reason we don't already just do this work using regex is because Solidity allows the constant keyword to be used in two contexts - constant declaration and function modifier.
• Regex remove the marked text . . . we need to preserve correct line numbers in this process as well.

[mttmartin]

No worries @h3ph4est7s! I'm glad to see the bounty go to you, since you could turn this around so quickly. :)

[h3ph4est7s]

@cgewecke to run effectively oraclize tests the bridge must be used but so far i haven't noticed any bad interaction with solidity-coverage the oraclize system is consisted of 3 parts, the client-code usingOraclize, the resolver and the actual contract. the 2 are deployed by the bridge and are not under any coverage because they are outside of scope. Also the PR https://github.com/sc-forks/solidity-coverage/pull/259 successfully correct the issue if usingOraclize is excluded but the perforance impact of the parser is still there. In other words we only care about the verification of the extending contract. About the patch i tried to tweak the functionality of the parser by traversing all the AST record without reparsing (its way more fast) by just keeping addition offsets for every block marker addition. For the visibility specifier i used empty spaces to keep the alignment but i have some misaligned brackets at a nesting point. My new approach will be to realign the AST offsets by affected part aka change the start and end values according to how many bytes added before that on every addition. @mttmartin Thank you for your cooperative spirit and kind words i really appreciate it.

[gitcoinbot]

Issue Status: 1. Open 2. Started 3. Submitted 4. Done

---

__Work for 400.0 DAI (400.0 USD @ $1.0/DAI) has been submitted by__:

1. @h3ph4est7s

@vs77bb please take a look at the submitted work:

• PR by @h3ph4est7s

---

• Learn more on the Gitcoin Issue Details page
• Questions? Checkout Gitcoin Help or the Gitcoin Slack
  $22,365.89 more funded OSS Work available on the Gitcoin Issue Explorer

[cgewecke]

For the visibility specifier i used empty spaces to keep the alignment but i have some misaligned brackets at a nesting point.

@h3ph4est7s Do you want add the work you did in this direction to #259? It's ok if it's not perfect but it will let me move it into a branch and maybe get it running. Thanks for your analysis of this stuff, super helpful.

[h3ph4est7s]

@cgewecke i pushed 6221e8966f8d1c2651eee6c0fcd11353d578c4c7, b39a31a76d26fbc01a22a5b39e24936f2e746fc1, 71320c06a13f3c62019d44a86b5d357aa2dfe3c9 and 7241af865ec386774f9b82ca66faaeb8072bb3c8 in https://github.com/sc-forks/solidity-coverage/pull/259 the first stage is completed according to the description of the process here https://github.com/sc-forks/solidity-coverage/issues/238#issuecomment-404629559 the second stage is not so simple.
If the start and end positions of a code location was successive it should be simple enough to add a +2 offset on every {block} addition to the next element.
This works if the statements are flat without any nesting. In the latter case the offset addition must be broken in half (+1) in each start and the other half in each end until the nest is resolved,
patterns like the followings has been observed:

25 = Object {start: 27074, end: 27177, nested: true}
26 = Object {start: 27107, end: 27117, nested: true}
27 = Object {start: 27168, end: 27177, nested: true}

and

55 = Object {start: 46271, end: 46372, nested: true}
56 = Object {start: 46320, end: 46372, nested: true}
57 = Object {start: 46351, end: 46372, nested: true}
58 = Object {start: 46426, end: 46561, nested: true}
59 = Object {start: 46475, end: 46561, nested: true}
60 = Object {start: 46506, end: 46561, nested: true}
61 = Object {start: 46540, end: 46561, nested: true}
62 = Object {start: 46615, end: 46716, nested: true}
63 = Object {start: 46664, end: 46716, nested: true}
64 = Object {start: 46695, end: 46716, nested: true}

A diff example of commit 7241af865ec386774f9b82ca66faaeb8072bb3c8 can be found here https://www.diffchecker.com/OWtBlP0x as also described in the commit message.

[cgewecke]

Ah ok interesting! I'm satisfied with this solution - great work @h3ph4est7s!

@vs77bb - @h3ph4est7s has completed the work this bounty successfully. Thanks again both of you for helping here.

[gitcoinbot]

Issue Status: 1. Open 2. Started 3. Submitted 4. Done

---

__The funding of 400.0 DAI (400.0 USD @ $1.0/DAI) attached to this issue has been approved & issued to @h3ph4est7s.__

• Learn more at on the Gitcoin Issue Details page
• Questions? Checkout Gitcoin Help or the Gitcoin Slack
• $28,596.00 more funded OSS Work available on the Gitcoin Issue Explorer

[vs77bb]

@h3ph4est7s just paid out! Great work here 🙂

[cgewecke]

Finally addressed this a bit. h3ph4est7s 's patch fix is available as an option starting with 0.5.10.

deepSkip: true

If you're skipping files/folders and are experiencing instrumentation hangs this works. If you're using mocks that need to be post-processed but skipping them because you don't want them in the report (Zeppelin is an example of this), this will cause problems.