Scanner report successfully uploaded but not processed in SonarQube

justus_bunsi · November 25, 2022, 9:34am

Hello community ,

I’m using self-hosted SonarQube Enterprise edition 9.7.0.61563 and experiencing an odd behavior regarding Scanner uploads to SonarQube during the last few days. This started a day after having a server freeze that took SonarQube down out of the sudden. There were some automatic attempts to restart the application during the outage that ended up in Elasticsearch shard errors. Unfortunately, I don’t have these error logs anymore. After the server issue was resolved, we were able to start SonarQube without any issues and in general there are no issues.

That said, here’s the odd behavior we experienced twice since that server freeze (2 days ago as of writing):

Jenkins generates a project analysis (for a pull request) using the official SonarScanner
Jenkins successfully posts that generated report file to SonarQube
Jenkins waits for the quality gate result from SonarQube and receives 404 Not Found errors for the successfully pushed report

Searching for the pull request in the project within SonarQube reveals that there is no such pull request analysis. Looking into the background tasks of the whole instance there is no task matching the ID that Jenkins was waiting for.

My first thought: There is a network issue and the POST request got lost or dropped somewhere. Surprisingly there is no evidence that this is the case. NGINX that handles all requests show that Jenkins successfully posted the report file to SonarQube. I can see the request in the NGINX logs. SonarQube itself logged a success for that request in its access.log but there is no entry inside ce.log indicating that the report was actually processed. The latter explains why there is no background task in the UI, right?

What’s even more concerning: One of the two times this happened there was another report upload for the same project (different pull request) at the very same second which was processed properly. There is no error log around that time.

Interestingly the scenario for the other occurrence (different SonarQube project) is completely different. There wasn’t even another report upload +/- 5 minutes around the missing one and no other background task seem to be running during that time.

I have temporarily enabled debug log level for the instance and am waiting for another occurrence that hopefully never happen.

Some thoughts I also had:

We have 2 workers for background tasks. Looks like this is no concurrency issue.
Maybe the maximum number of connections is reached? - But this wouldn’t explain the success entry in the logs, right?
Is there an undetected issue with the Elasticsearch data in es7 directory and we should’ve cleared it before starting SonarQube after the server issue?

I’d be extremely happy for any ideas how I can better troubleshoot this somewhat random issue. Is there anything I am missing or anything you’d need from me that helps?

I’ve seen Upload report fails. Please help! but that seem to not cover my situation.

Best regards,
Steven

Colin · November 28, 2022, 2:14pm

Hey there

Thanks for the detailed report.

Is there any chance that after the freeze with various services restarts you accidentally ended up with two SonarQube instances/services both connected to the same database? This can cause some weird behavior?

You might check connections on the Database side, or just run a jps command on your server to get an idea of what processes are running.

justus_bunsi · November 28, 2022, 5:23pm

Hi @Colin, thanks for the hint. I’ve checked connections on the database side for both of our instances (production, staging). The production instance was the one having the shutdown and auto-restarts, the staging instance is hosted on another server and was not affected by the incident and doesn’t show the odd behavior.

Both instances have the same amount of connections: 21 (as of writing this).
At that time of the day both instances are quite idle. Not sure if it is common connection count for idle instances?

We are using the official Docker image where jps seems to be missing. The openjdk alpine package should provide it though. Is there some SonarQube internal way of accessing the amount of processes?

Colin · November 30, 2022, 4:02pm

Hey there.

Thanks for the follow-up.

If you’re using Docker, I’m not worried about there being multiple processes running within that container. Although it does make me wonder if somehow, around the time of the incident you’re describing, a second container was started somehow targeting the same database.

I wouldn’t worry about connection count as it’s displayed in SonarQube (it very rarely comes into play, even on huge instances), but more about connections to the database overall (which you find on the database-side, not SonarQube-side). This is what would indicate if something else, like another instance, was connecting to the database.

I also wouldn’t worry about Elasticsearch as it only comes into play much later during report processing.

Have you experienced the lost CE tasks since the 2 hiccups earlier this week (i.e. – is the issue still recurring?)

justus_bunsi · December 2, 2022, 8:34am

Hi @Colin.

Although it does make me wonder if somehow, around the time of the incident you’re describing, a second container was started somehow targeting the same database.

Unfortunately, I cannot rule that out. Resolving this server freeze issue took quite a while. During that time the VM was still somehow running but was not reachable at all.

Have you experienced the lost CE tasks since the 2 hiccups earlier this week (i.e. – is the issue still recurring?)

No, these two hiccups regarding lost CE tasks were the only ones.The last one on Friday 2022-11-25.

I have temporarily enabled debug log level for the instance[…]

I was about to close this topic right before I realized that the debug log level wasn’t active anymore. It should’ve been since there was no planned SonarQube restart since then. Turns out SonarQube had another restart loop last Saturday (2022-11-26) due to a network configuration that destabilized our Kubernetes cluster connectivity and lead to SonarQube being restarted. I really need to improve my monitoring on that regards. I was able to save the latest container stop logs and it looks like Elasticsearch didn’t liked those restarts either. 6 restarts later, when that network issue was fully resolved, SonarQube started successfully. Below you can find the stacktrace from the last container stop. Do you think we should stop SonarQube gracefully, clean up Elasticsearch data and start the application again?

Latest restart logs

2022.11.26 10:18:04 INFO  app[][o.s.a.AppFileSystem] Cleaning or creating temp directory /opt/sonarqube/temp
2022.11.26 10:18:04 INFO  app[][o.s.a.es.EsSettings] Elasticsearch listening on [HTTP: 127.0.0.1:9001, TCP: 127.0.0.1:38635]
2022.11.26 10:18:04 INFO  app[][o.s.a.ProcessLauncherImpl] Launch process[ELASTICSEARCH] from [/opt/sonarqube/elasticsearch]: /opt/sonarqube/elasticsearch/bin/elasticsearch
2022.11.26 10:18:04 INFO  app[][o.s.a.SchedulerImpl] Waiting for Elasticsearch to be up and running
2022.11.26 10:18:05 INFO  es[][o.e.n.Node] version[7.17.5], pid[31], build[default/tar/8d61b4f7ddf931f219e3745f295ed2bbc50c8e84/2022-06-23T21:57:28.736740635Z], OS[Linux/5.10.0-12-amd64/amd64], JVM[Alpine/OpenJDK 64-Bit Server VM/11.0.15/11.0.15+10-alpine-r0]
2022.11.26 10:18:05 INFO  es[][o.e.n.Node] JVM home [/usr/lib/jvm/java-11-openjdk]
2022.11.26 10:18:05 INFO  es[][o.e.n.Node] JVM arguments [-XX:+UseG1GC, -Djava.io.tmpdir=/opt/sonarqube/temp, -XX:ErrorFile=../logs/es_hs_err_pid%p.log, -Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -Djna.tmpdir=/opt/sonarqube/temp, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dio.netty.allocator.numDirectArenas=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j2.formatMsgNoLookups=true, -Djava.locale.providers=COMPAT, -Dcom.redhat.fips=false, -Des.enforce.bootstrap.checks=true, -Xmx2G, -Xms2G, -XX:+HeapDumpOnOutOfMemoryError, -Des.path.home=/opt/sonarqube/elasticsearch, -Des.path.conf=/opt/sonarqube/temp/conf/es, -Des.distribution.flavor=default, -Des.distribution.type=tar, -Des.bundled_jdk=false]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] loaded module [analysis-common]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] loaded module [lang-painless]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] loaded module [parent-join]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] loaded module [reindex]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] loaded module [transport-netty4]
2022.11.26 10:18:05 INFO  es[][o.e.p.PluginsService] no plugins loaded
2022.11.26 10:18:05 ERROR es[][o.e.b.ElasticsearchUncaughtExceptionHandler] uncaught exception in thread [main]
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])?
	at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:173) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Elasticsearch.execute(Elasticsearch.java:160) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.cli.EnvironmentAwareCommand.execute(EnvironmentAwareCommand.java:77) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.cli.Command.mainWithoutErrorHandling(Command.java:112) ~[elasticsearch-cli-7.17.5.jar:7.17.5]
	at org.elasticsearch.cli.Command.main(Command.java:77) ~[elasticsearch-cli-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:125) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:80) ~[elasticsearch-7.17.5.jar:7.17.5]
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])?
	at org.elasticsearch.env.NodeEnvironment.<init>(NodeEnvironment.java:328) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.node.Node.<init>(Node.java:429) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.node.Node.<init>(Node.java:309) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Bootstrap$5.<init>(Bootstrap.java:234) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Bootstrap.setup(Bootstrap.java:234) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Bootstrap.init(Bootstrap.java:434) ~[elasticsearch-7.17.5.jar:7.17.5]
	at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:169) ~[elasticsearch-7.17.5.jar:7.17.5]
	... 6 more
uncaught exception in thread [main]
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])?
	at org.elasticsearch.env.NodeEnvironment.<init>(NodeEnvironment.java:328)
	at org.elasticsearch.node.Node.<init>(Node.java:429)
	at org.elasticsearch.node.Node.<init>(Node.java:309)
	at org.elasticsearch.bootstrap.Bootstrap$5.<init>(Bootstrap.java:234)
	at org.elasticsearch.bootstrap.Bootstrap.setup(Bootstrap.java:234)
	at org.elasticsearch.bootstrap.Bootstrap.init(Bootstrap.java:434)
	at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:169)
	at org.elasticsearch.bootstrap.Elasticsearch.execute(Elasticsearch.java:160)
	at org.elasticsearch.cli.EnvironmentAwareCommand.execute(EnvironmentAwareCommand.java:77)
	at org.elasticsearch.cli.Command.mainWithoutErrorHandling(Command.java:112)
	at org.elasticsearch.cli.Command.main(Command.java:77)
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:125)
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:80)
For complete error details, refer to the log at /opt/sonarqube/logs/sonarqube.log
2022.11.26 10:18:05 WARN  app[][o.s.a.p.AbstractManagedProcess] Process exited with exit value [ElasticSearch]: 1
2022.11.26 10:18:05 INFO  app[][o.s.a.SchedulerImpl] Process[ElasticSearch] is stopped
2022.11.26 10:18:05 ERROR app[][o.s.a.p.EsManagedProcess] Failed to check status
org.elasticsearch.ElasticsearchException: java.lang.InterruptedException
	at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2695)
	at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:2171)
	at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:2137)
	at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:2105)
	at org.elasticsearch.client.ClusterClient.health(ClusterClient.java:151)
	at org.sonar.application.es.EsConnectorImpl.getClusterHealthStatus(EsConnectorImpl.java:64)
	at org.sonar.application.process.EsManagedProcess.checkStatus(EsManagedProcess.java:92)
	at org.sonar.application.process.EsManagedProcess.checkOperational(EsManagedProcess.java:84)
	at org.sonar.application.process.EsManagedProcess.isOperational(EsManagedProcess.java:62)
	at org.sonar.application.process.ManagedProcessHandler.refreshState(ManagedProcessHandler.java:223)
	at org.sonar.application.process.ManagedProcessHandler$EventWatcher.run(ManagedProcessHandler.java:288)
Caused by: java.lang.InterruptedException: null
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040)
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345)
	at org.elasticsearch.common.util.concurrent.BaseFuture$Sync.get(BaseFuture.java:243)
	at org.elasticsearch.common.util.concurrent.BaseFuture.get(BaseFuture.java:75)
	at org.elasticsearch.client.RestHighLevelClient.performClientRequest(RestHighLevelClient.java:2692)
	... 10 common frames omitted
2022.11.26 10:18:05 INFO  app[][o.s.a.SchedulerImpl] SonarQube is stopped

We don’t use the official Helm Chart yet. Currently it’s a bare Deployment with database and SonarQube wrapped inside one pod, running for a few years now. We did the sysctl adjustments on the node manually.

Best regards,
Steven

justus_bunsi · December 7, 2022, 2:08pm

An update after 5 days of SonarQube running without any interruption: There was no other hiccup. It seems that this issue has been resolved on its own. Thank you @Colin for your input last week.

system · December 14, 2022, 2:08pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.