Java project scan hangs on "Analyzing XXX ucfgs to detect vulnerabilities"

java
sonarcloud

(Asmoiseenko) #1

Hello.
Maven Sonar Plugin usually takes about 10 minutes to complete on our project, but since Sept 7 it hangs for 1.5 hour and more, then we simply kill Jenkins job

Partial output before (sensitive data removed):

[INFO] -------------  Scan XXX
[INFO] Base dir: XXX
[INFO] Working dir: XXX
[INFO] Source encoding: UTF-8, default locale: en_US
[INFO] Index files
[INFO] 0 files indexed
[INFO] Sensor SonarJavaXmlFileSensor [java]
[INFO] Sensor SonarJavaXmlFileSensor [java] (done) | time=0ms
[INFO] Sensor Zero Coverage Sensor
[INFO] Sensor Zero Coverage Sensor (done) | time=1852ms
[INFO] Sensor JavaSecuritySensor [security]
[INFO] Analyzing 22704 ucfgs to detect vulnerabilities.
[INFO] Sensor JavaSecuritySensor [security] (done) | time=55208ms
[INFO] Sensor CSharpSecuritySensor [security]
[INFO] Analyzing 0 ucfgs to detect vulnerabilities.
[INFO] Sensor CSharpSecuritySensor [security] (done) | time=13ms
[INFO] Sensor Java CPD Block Indexer
[INFO] Sensor Java CPD Block Indexer (done) | time=3182ms
[INFO] 1635 files had no CPD blocks
[INFO] Calculating CPD for 4406 files
[INFO] CPD calculation finished
[INFO] Analysis report generated in 5002ms, dir size=48 MB
[INFO] Analysis reports compressed in 32255ms, zip size=22 MB
[INFO] Analysis report uploaded in 3512ms
[INFO] ANALYSIS SUCCESSFUL, you can browse XXX
[INFO] Note that you will be able to access the updated dashboard once the server has processed the submitted analysis report
[INFO] More about the report processing at XXX
[INFO] Task total time: 11:43.068 s

Now output looks like this:

[INFO] -------------  Scan XXX
[INFO] Base dir: XXX
[INFO] Working dir: XXX
[INFO] Source encoding: UTF-8, default locale: en_US
[INFO] Index files
[INFO] 0 files indexed
[INFO] Sensor SonarJavaXmlFileSensor [java]
[INFO] Sensor SonarJavaXmlFileSensor [java] (done) | time=0ms
[INFO] Sensor Zero Coverage Sensor
[INFO] Sensor Zero Coverage Sensor (done) | time=1167ms
[INFO] Sensor JavaSecuritySensor [security]
[INFO] UCFGs: 22763, excluded: 21941, source entrypoints: 822
[INFO] Analyzing 22763 ucfgs to detect vulnerabilities.
[INFO] rule: S3649, entrypoints: 33
[INFO] rule: S2076, entrypoints: 0
[INFO] rule: S2091, entrypoints: 0
[INFO] rule: S2078, entrypoints: 0
[INFO] rule: S2631, entrypoints: 635
[WARNING] [JOURNAL_FLUSHER] WARNING Journal flush operation took 3,556ms last 8 cycles average is 444ms
Build was aborted

I saw similar issues Suddenly analysis takes a long time to finish
but seems like solution was on the Sonar side. Should I disable particular rules for now?

Thank you


(Nicolas Peru) #4

Hi,

This seems linked to latest deployment of SonarSecurity.
Can you specify which quality profile you are using ? the Sonar Way ?
From the log I can deduce that there is two possibilities for the flaw to pop up : Either the analysis get stuck on rule S2631 (which we can verify by disabling this rule) or the analysis is stuck on computation of entry points of rule S2083.

So, could you please try to run an analysis with a quality profile disabling S2631 and let us know if the analysis is still stuck. If no, good, we have a culprit, if yes, let’s retry by having only S2083 disabled and again, watch the outcome if analysis is stuck or not.

With this information we would be able to move forward.

In the meantime, to avoid such investigation in the future, I created https://jira.sonarsource.com/browse/SONARSEC-218 to improve those kind of investigations.


(Asmoiseenko) #5

Hi, Nicolas. S2631 is disabled, I’ll provide update in 12 hours after nightly build.
Thanks


(Asmoiseenko) #6

Hi, Nicolas. You are right, scan completed in expected 11 minutes with rule S2631 disabled. What are the next steps? Do you want us to collect additional information to troubleshoot this?


(Dinesh Bolkensteyn) #7

@asmoiseenko I see this suspect message in your logs: [WARNING] [JOURNAL_FLUSHER] WARNING Journal flush operation took 3,556ms last 8 cycles average is 444m. While I am not a Java JVM ninja, my past experience tells me that this is typically a sign of a JVM running out of memory.

Could you please retry an analysis with rule S2631 enabled but by giving more memory to the JVM. In Maven, you can do so by setting the MAVEN_OPTS environment variable to -Xmx2048m to allocate 2GB of RAM to the JVM (see the official documentation).


(Asmoiseenko) #8

Thanks, Dinesh. Increased Xmx from 1024 to 2048m. Will provide update in about 12 hours


(Dinesh Bolkensteyn) #9

How did it go @asmoiseenko?


(Asmoiseenko) #10

Sorry, we skipped last scan, so waiting another 12 hours. Will let you know. Thanks


(Asmoiseenko) #11

Scan is completed now with S2631 enabled and xmx set to 2048m. Took 28 minutes. Usual scan run time is about 10 minutes. @@dbolkensteyn, do you think it can be improved or is it expected performance for S2631 rule? Thanks for your help.


(Nicolas Peru) #12

From the info you are giving us it seems that rule S2631 is taking quite some memory for your project.
But here without the source code of your project we are a bit stuck now on our side.

Two things though :

  • from the log of entry points I can deduce your project that is a web project and making quite some usage of regex or String.split/matches methods, this seems to trigger a complex analysis on this rule : I would be interested by your analysis of the issues eventually found on that rule.

  • We are starting some thoughts, originated from this thread, about how to get some more debug information without you sharing your whole project. (What we would be interested is the call graph of your project).


(Asmoiseenko) #13

You are correct, web app and of course we are using split, but looks like we don’t have any S2631 issues

Let me know what project data we need to provide to help you resolve this issue.


(Dinesh Bolkensteyn) #14

I’m really glad to learn that the project analysis completed within some reasonable amount of time with the rule enabled @asmoiseenko :slight_smile:

Could you share the updated analysis logs? If possible, having them timestamped would help (e.g. using Jenkins Timestamper’s plugin). Several elements are of interest to us:

  1. Are there still any [JOURNAL_FLUSHER] WARNING Journal flush messages present, in which case you could try to further increase the amount of memory to see if this impacts the analysis time
  2. What is the new total time for JavaSecuritySensor [security] (done) | time=...

The ideal situation is if you can share the generated UCFG files (*.pb) privately with us for further investigation. Those are binary files that contain, for each method, the list of all other invoked methods. With those files, we can re-run the analysis of rule S2631 on our side and profile it and see if anything abnormal is going on.

That being said, a jump from 10 minutes to 28 minutes does not sound entirely crazy to me and I am not 100% sure that there is something to fix on our side. Is that time something you can live with?


(Dinesh Bolkensteyn) #15

Thank you for sharing additional data @asmoiseenko. The investigation on our side is still going on.

I’d like to clarify one point from my last post:

a jump from 10 minutes to 28 minutes does not sound entirely crazy to me and I am not 100% sure that there is something to fix on our side

What I meant by that is that I cannot guarantee you that we will be able to go back to to the initial 10 minutes. Rule such as S2631 detect advanced security vulnerabilities and by definition requires quite a bit of computation. There is a trade-off to be found between how powerful the analyzers are and how much time one is willing to dedicate to the analysis, and we definitely value short feedback loops.


(Asmoiseenko) #17

Thanks @dbolkensteyn. We understand this, will plan more resources to run scans