Upgrade from SonarQube 8.9.9 to 9.9.2 causes MSSQL deadlocks

Hi,

After upgrading from SonarQube 8.9.9 Community to 9.9.2 we see MSSQL deadlocks in our logs:

"### SQL: delete from properties where prop_key=? and component_uuid=? and user_uuid is null

Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 80) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction."

We are running SonarQube on Debian Bullseye11.5, which is using OpenJDK Runtime Environment (build 17.0.6+10-LTS)
We use MSSQL 2016 as our database server.

We followed your best practices to enable is_read_committed_snapshot_on=true on the database, suggested in your installation, In another article (MSSQL DeadLock with workerCount ) a user suggested that setting sonar.ce.workerCount=1 had helped him getting rid of these errors, but after doing that we still see these errors. What makes me scratch my head is “delete from properties where prop_key=? and component_uuid=? and user_uuid is null” which in my opinion would never delete anything, and when i asked my DBA what such a query would do he responded “I would expect it to fail due to syntax error. Query parser can not parse that statement with question marks”.

Is sonarqube failing to log the correct values in the query, or might our database have been corrupted during the upgrade?

Any insight would help us tremendously

Kind regards,

Jonas

Hey there.

Those question marks bit misleading – they aren’t literally being passed to the database server like that.

Is READ_COMMITTED_SNAPSHOT set on your SQL server as documented? This not being set is the most common cause of deadlocks.

Hi,

Yes, it is indeed.

Kind regards

Jonas

Thanks. I actually missed that part in your first message.

  • Is your SQL Server performing well? Regarding CPU, memory, disk space…
  • Are you database indexes/statistics up-to-date?

And to be super clear, you have READ_COMMITTED_SNAPSHOT set to 1, not is_read_committed_snapshot_on set to true, correct?

Nope, thats a typo on my behalf.

Just to be sure i will verify it with the DBAs

I can confirm from the DBA who did the change, that it’s indeed set correctly:

READ_COMMITTED_SNAPSHOT=1

On that database.

Kind regards,

Jonas

Hi all,

This error still persists on sonar after all this time. Last weekend we upgraded sonarqube to 9.9.8 in the hope that this was something caused by the database connector or some obscure bug in sonar, however we still see the same issues;

…
…
2025.01.21 16:08:08 ERROR web[AZR51aUxegWV2rC8F+fZ][o.s.s.w.WebServiceEngine] Fail to process request http://SONARURL/api/settings/set?component=com.ponent%3AAPPNAME%3Abugfix-CPIT-11630_alt&key=sonar.core.startTime&value=2022-08-12T17%3A41%3A54%2B0200
org.apache.ibatis.exceptions.PersistenceException:

Error updating database. Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 303) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

The error may exist in org.sonar.db.property.PropertiesMapper

The error may involve org.sonar.db.property.PropertiesMapper.delete-Inline

The error occurred while setting parameters

SQL: delete from properties where prop_key=? and component_uuid=? and user_uuid is null

Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 303) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

…
…
Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 303) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

As verified in this thread before, we indeed have READ_COMMITTED_SNAPSHOT=1 on the database, for both our enterprise and community version of sonarcube, however we only see this issue on sonarqube community 9.9.8

Any help would make this application a ton more useful to us, has anyone ran into the same issue?

Kindest of regards
Jonas

Hey @Jonasandersson

I’m actually really puzzled by this specific web request.

sonar.core.startTime is a global server setting that has no business being set via Web API (like its name would lead you to believe, it’s set at start time), and certainly not tied to a specific component.

Where is this web request coming from? You should be able to hunt it down by looking at your access.log file. Do you see any other weird requests from the same origin / user agent?

What I’m trying to get at is that if something (bad actor, internal automation gone rogue) is flooding your SonarQube server with bad requests, it’s not unreasonable that some erroneous behavior would follow.

Hi Colin,

And thanks for the very fast response. As suspected, this request came from Bitbucket Datacenter v8.19.14, which uses the Mibex Include Code Quality for Bitbucket (version 7.2.0), which according to Mibex:
supports SonarQube™ compatibility:

  • v7.7 or newer
  • Community, Commercial editions and SonarCloud™ support

The request doesn’t come alone, here are some other request that happens before and after:

<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.auth.saml.user.name&value=http%3A%2F%2Fschemas.microsoft.com%2Fidentity%2Fclaims%2Fdisplayname HTTP/1.1" 400 914 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:07 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.core.id&value=F390DDA4-AYHif_UzsJTGt-y94WVk HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:07 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.coverage.jacoco.xmlReportPaths&values=target%2Fsite%2Fjacoco-aggregate%2Fjacoco.xml&values=target%2Fsite%2Fjacoco%2Fjacoco.xml HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.auth.saml.user.login&value=http%3A%2F%2Fschemas.xmlsoap.org%2Fws%2F2005%2F05%2Fidentity%2Fclaims%2Fonprem_sam_account_name%2FsamAccountName HTTP/1.1" 400 367 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "GET /api/qualityprofiles/search?projectKey=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt HTTP/1.1" 200 2973 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "GET /api/projects/search?projects=com.<company>.cockpit.rfqenrichmentservice%3Acockpit-rfq-enrichment-service%3Afeature-CPIT-11497 HTTP/1.1" 200 1986 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "GET /api/qualityprofiles/search?projectKey=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Amaster HTTP/1.1" 200 2424 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:08 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonaranalyzer-cs.nuget.packageVersion&value=8.51.0.59060 HTTP/1.1" 400 378 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:06 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.issue.ignore.allfile&fieldValues=%7B%22fileRegexp%22%3A%22%2F%2F+Generated+by+the+protocol+buffer+compiler.++DO+NOT+EDIT%22%7D HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:07 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.terraform.file.suffixes&values=.tf HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:07 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.ruby.file.suffixes&values=.rb HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:09 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonaranalyzer-cs.nuget.packageVersion&value=8.51.0.59060 HTTP/1.1" 400 378 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:07 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.terraform.file.suffixes&values=.tf HTTP/1.1" 204 1632 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:09 +0100] "POST /api/settings/set?component=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Abugfix-CPIT-11630_alt&key=sonar.auth.github.allowUsersToSignUp&value=true HTTP/1.1" 400 926 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"
<Bitbucket.IP> - - [21/Jan/2025:16:08:09 +0100] "GET /api/qualitygates/get_by_project?project=com.<company>.cockpit.appserver.tradingengine%3Acockpit-trading-engine-app-server%3Amaster HTTP/1.1" 200 1321 "-" "Apache-HttpClient/4.5.14 (Java/17.0.13)"

So you are suggesting the plugin should not expect these requests to work, and we might want to talk to Mibex about the plugin and the issue it creates?

Kindest of regards
Jonas

Another thing that strikes me as odd is that the request is recieved and then gets a 400 (bad request) however, sonarcube still seems to process it, as if it was a good request, example here:

2025.01.21 17:23:46 ERROR web[AZR51aUxegWV2rC8GNMv][o.s.s.w.WebServiceEngine] Fail to process request http:///api/settings/set?component=com.company.tradestore
.enrichment%3Atradestore-enrichment-parent%3Afeature-TCAP-4205-ThroughtputTest&key=sonar.dbcleaner.daysBeforeDeletingClosedIssues&value=30
org.apache.ibatis.exceptions.PersistenceException:

Error updating database. Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 303) was deadlocked on lock resources with another process and has been chosen

as the deadlock victim. Rerun the transaction.

The error may exist in org.sonar.db.property.PropertiesMapper

The error may involve org.sonar.db.property.PropertiesMapper.delete-Inline

The error occurred while setting parameters

SQL: delete from properties where prop_key=? and component_uuid=? and user_uuid is null

Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 303) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Re

run the transaction.
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:196)
at org.apache.ibatis.session.defaults.DefaultSqlSession.delete(DefaultSqlSession.java:209)

If it was a completely bad request would it not be dismissed as a wrongful request?

Kind regards

Jonas

Hey @Jonasandersson

Yes, I think it’s worth mentioning to Mibex that some of these API calls make no sense.

Setting sonar.auth.saml.user.login on a project (or any component)? It’s nonsense.

Based on the timestamps, it also seems that the integration is sending a lot of requests at once—so fast that the timestamps end up out of order. SonarQube shouldn’t handle this with a deadlock, but this is still not expected input.

Why is this integration configuring your SonarQube Server settings at all?

I ran some additional tests with some unexpected results – SonarQube doesn’t actually throw away all of these requests (sonar.core.startTime is successfully set on a component, although it’s meaningless).

This is also a valid request (setting housekeeper settings on a component). But again, why would this integration be setting this?

So right now my takeaways are that:

  • This integration is behaving poorly, bombarding your SonarQube server with bad requests. You should reach out to Mibex.
  • Potentially, we have an issue with deadlocks when there’s a lot of traffic heading towards POST API/settings/set. I’ll flag this for attention, but we also have no other reports for the time being (I checked through our internal ServiceDesk as well).

Hi Colin,

First things first we would like to thank you, you highlighted a lot issues and made us start looking in a different directions that ultimately helped us find the root-cause. You were also correct about Mibex plugins calls to Sonar. We have let them know of these issues and they are now also looking into improvements to their plugin, because of your observations.
We are not over the water yet and are still working on a fix, but we figure we would take a minute to thank you.

Kind regards
Jonas

1 Like

That’s very nice of you, and I’m sorry it took so long for us to get here! I wrote this off as an issue with your DB one year ago, but seeing this in your updated report was the key to understanding that something else is going on.