Error Jgit with sonar-scanner

rfuser · July 21, 2022, 1:58pm

Hi,

We encountered an error when running sonar-scanner on services provider (from 4.6 to latest version)

15:34:33.534 DEBUG: delta [ns] since modification FileSnapshot failed to detect
count, failures, racy limit [ns], delta min [ns], delta max [ns], delta avg [ns], delta stddev [ns]
4925, 126, 10000, 2246000.0, 5860000.0, 4016055.5555555555, 1049620.9624854526
15:34:33.535 DEBUG: FileStoreAttributes[fsTimestampResolution=4 µs, minimalRacyInterval=5,860 µs]
15:34:40.521 INFO: empty line
15:34:50.521 INFO: 
15:35:00.522 INFO: 
15:35:10.522 INFO: 
15:35:20.522 INFO: 
15:35:30.522 INFO: 
15:35:40.522 INFO: 
15:35:50.523 INFO: 
15:36:00.523 INFO: 
15:36:10.523 INFO: 
15:36:20.523 INFO: 
15:36:30.524 INFO: 
15:36:40.524 INFO: 
[... same]
- DEBUG: loading config FileBasedConfig[/root/.config/jgit/config]
- DEBUG: Native git blame failed. Falling back to jgit: app-android/app/src/test/kotlin/file.kt
java.lang.IllegalStateException: Command execution exited with code: 128
at org.sonar.scm.git.ProcessWrapperFactory$ProcessWrapper.execute(ProcessWrapperFactory.java:77)
at org.sonar.scm.git.GitBlameCommand.blame(GitBlameCommand.java:122)
at org.sonar.scm.git.CompositeBlameCommand.blame(CompositeBlameCommand.java:123)
at org.sonar.scm.git.CompositeBlameCommand.lambda$blame$0(CompositeBlameCommand.java:83)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
[... same]
infinite ...

Does someone have an idea which can cause it ?

ganncamp · July 21, 2022, 3:10pm

Hi,

Welcome to the community!

What version of SonarQube are you using?

Also, were there any “Caused by” lines in the stacktrace? If so, could we have the full stacktrace, please?

Ann

rfuser · July 22, 2022, 9:21am

Hi, thanks for the welcome

We are using Sonarqube 9.5 (56709) developer edition. The problem appeared after upgrade from 9.1 (it could be related, idk).

There are no ‘caused by’ lines at the date of problem (sonarqube logs)
Only ‘caused by’ lines at the date of upgrade :

java.lang.IllegalStateException: failed to obtain node locks, tried [[/opt/sonarqube/data/es7]] with lock id [0]; maybe these locations are not writable or multiple nodes were started without increasing [node.max_local_storage_nodes] (was [1])?

org.elasticsearch.bootstrap.StartupException: java.lang.IllegalStateException: failed to obtain node locks, tried [[/opt/sonarqube/data/es7]] with lock id [0]; maybe these locations are not writable or multiple nodes were started without increasing [node.max_local_storage_nodes] (was [1])?

Caused by: java.lang.IllegalStateException: failed to obtain node locks, tried [[/opt/sonarqube/data/es7]] with lock id [0]; maybe these locations are not writable or multiple nodes were started without increasing [node.max_local_storage_nodes] (was [1])?

Here, it’s the full log of sonar scanner :
log-sonarqube-post.txt (44.6 KB)

Have a nice day

ganncamp · July 22, 2022, 1:10pm

Hi,

Thanks for the log. I don’t see the error in it. Has the problem gone away?

Ann

rfuser · July 22, 2022, 2:24pm

No there is still error or infinite file analyse
Sometimes this error appears if i tweak some debug parameter / sonar.properties configurations.

here log with this error
log-sonarqube-post2.txt (43.7 KB)

ganncamp · July 22, 2022, 5:23pm

Hi,

Thanks for the logging. I appreciate your effort to compress the repeated data, but it really would be nice to have the full, unedited file (with only names/paths redacted as necessary).

Since you’ve edited, I need to ask more questions:

15:37:33.079 DEBUG: Native git blame failed. Falling back to jgit: folder/src/file.kt
java.lang.IllegalStateException: Command execution exited with code: 128
   at org.sonar.scm.git.ProcessWrapperFactory$ProcessWrapper.execute(ProcessWrapperFactory.java:77)
   at org.sonar.scm.git.GitBlameCommand.blame(GitBlameCommand.java:122)
   at org.sonar.scm.git.CompositeBlameCommand.blame(CompositeBlameCommand.java:123)
   at org.sonar.scm.git.CompositeBlameCommand.lambda$blame$0(CompositeBlameCommand.java:83)
   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
   at java.base/java.lang.Thread.run(Thread.java:829)
15:37:33.079 DEBUG: Native git blame failed. Falling back to jgit: folder/src/other-file.kt
java.lang.IllegalStateException: Command execution exited with code: 128
   at org.sonar.scm.git.ProcessWrapperFactory$ProcessWrapper.execute(ProcessWrapperFactory.java:77)
   at org.sonar.scm.git.GitBlameCommand.blame(GitBlameCommand.java:122)
   at org.sonar.scm.git.CompositeBlameCommand.blame(CompositeBlameCommand.java:123)
   at org.sonar.scm.git.CompositeBlameCommand.lambda$blame$0(CompositeBlameCommand.java:83)
   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
   at java.base/java.lang.Thread.run(Thread.java:829)
15:37:33.079 DEBUG: Native git blame failed. Falling back to jgit: folder/src/other-file.kt
java.lang.IllegalStateException: Command execution exited with code: 128
   at org.sonar.scm.git.ProcessWrapperFactory$ProcessWrapper.execute(ProcessWrapperFactory.java:77)
   at org.sonar.scm.git.GitBlameCommand.blame(GitBlameCommand.java:122)
   at org.sonar.scm.git.CompositeBlameCommand.blame(CompositeBlameCommand.java:123)
   at org.sonar.scm.git.CompositeBlameCommand.lambda$blame$0(CompositeBlameCommand.java:83)
   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
   at java.base/java.lang.Thread.run(Thread.java:829)
15:37:33.079 DEBUG: Native git blame failed. Falling back to jgit: folder/src/other-file.kt
java.lang.IllegalStateException: Command execution exited with code: 128
   at org.sonar.scm.git.ProcessWrapperFactory$ProcessWrapper.execute(ProcessWrapperFactory.java:77)
   at org.sonar.scm.git.GitBlameCommand.blame(GitBlameCommand.java:122)
   at org.sonar.scm.git.CompositeBlameCommand.blame(CompositeBlameCommand.java:123)
   at org.sonar.scm.git.CompositeBlameCommand.lambda$blame$0(CompositeBlameCommand.java:83)
   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
   at java.base/java.lang.Thread.run(Thread.java:829)

Does this represent errors on 4 different files? 2 files? (Some other count?)

16:00:10.550 INFO: 4/11 source files have been analyzed
[.. same]
16:18:10.571 INFO: 4/11 source files have been analyzed
Task was aborted else it goes until timeout (more than 2 hour)

Is the implications that the error set repeats over & over until you give up and quit the job?

Thx,
Ann

rfuser · July 25, 2022, 8:33am

Hello,

I compressed only the same line output and changed the path and file name
All [annotation] just means ‘same line’ than above&below.

16:00:10.550 INFO: 4/11 source files have been analyzed
[.. same]
16:18:10.571 INFO: 4/11 source files have been analyzed
Task was aborted

[else it goes until timeout (more than 2 hour)]

About it, yes the […same] repeat over and over until i cancel the job or it reached the timeout.

ganncamp · July 25, 2022, 2:08pm

Hi,

Okay, thanks for the detail. We made changes in recent versions to Git blame retrieval, so I’ve called for more expert attention on this.

Ann

rfuser · July 26, 2022, 7:58am

Hello,

Thanks, i will keep an eyes on the next version.

rfuser · July 28, 2022, 10:26am

Hello,

Have you some information to display or understand output at these blank INFO line :

INFO:
INFO:
INFO:
INFO:

-X parameter changes nothing and output is always blank.
How can i debug and get information about it plz ?

Wouter_Admiraal · August 12, 2022, 1:02pm

Hi @rfuser,

Does this happen on multiple projects or only 1 specific one? Are there any symbolic links in your project, or git submodules?

rfuser · August 22, 2022, 1:30pm

hello @Wouter_Admiraal
It happens only on 2 specific project. There are not symbolics links.

Wouter_Admiraal · September 2, 2022, 2:03pm

Hi @rfuser,

If it only happens on 2 projects, it is likely they have at least something that distinguishes them from the others. Is there anything that sets these 2 projects apart? If they have no symlinks, do they have Git submodules? Or something else? It just seems like it’s entering an infinite loop (hence my question about symlinks; but perhaps it’s something else).