We got a DB migration error when upgrading SonarQube Community Edition from 9.9.0 LTS to 10.0.0.68432 (zip installation on RHEL 7). Our database is Oracle 19C. The installed JDBC driver is ojdbc8 19.17.0.0.
It appears to be an issue with the SQL command being executed during the migration step ‘Remove orphan rules in Quality Profiles’. From the log, it seems to be the first migration step executed. Hopefully, someone can shed some light on this issue! For now, we just had to roll back to 9.9.0 LTS.
From web.log:
2023.04.06 12:48:26 INFO web[][o.s.s.p.d.m.DatabaseMigrationImpl] Starting DB Migration and container restart
2023.04.06 12:48:26 INFO web[][DbMigrations] Executing DB migrations...
2023.04.06 12:48:26 INFO web[][DbMigrations] #100000 'Remove orphan rules in Quality Profiles'...
2023.04.06 12:48:26 ERROR web[][DbMigrations] #100000 'Remove orphan rules in Quality Profiles': failure | time=40ms
2023.04.06 12:48:26 ERROR web[][DbMigrations] Executed DB migrations: failure | time=41ms
2023.04.06 12:48:26 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration failed | time=238ms
2023.04.06 12:48:26 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration ended with an exception
org.sonar.server.platform.db.migration.step.MigrationStepExecutionException: Execution of migration step #100000 'Remove orphan rules in Quality Profiles' failed
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:79)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:67)
at com.google.common.collect.ImmutableList.forEach(ImmutableList.java:422)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:52)
at org.sonar.server.platform.db.migration.engine.MigrationEngineImpl.execute(MigrationEngineImpl.java:54)
at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doUpgradeDb(DatabaseMigrationImpl.java:105)
at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doDatabaseMigration(DatabaseMigrationImpl.java:80)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.IllegalStateException: Error during processing of row: [uuid=AX3iVhstwiSjp8yPHWT4,profile_uuid=AX3iVkJEwiSjp8yPHWhr,rule_uuid=5112]
at org.sonar.server.platform.db.migration.step.SelectImpl.newExceptionWithRowDetails(SelectImpl.java:89)
at org.sonar.server.platform.db.migration.step.SelectImpl.scroll(SelectImpl.java:81)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.execute(RemoveOrphanRulesFromQualityProfiles.java:47)
at org.sonar.server.platform.db.migration.step.DataChange.execute(DataChange.java:44)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:75)
... 9 common frames omitted
Caused by: java.sql.SQLSyntaxErrorException: ORA-00933: SQL command not properly ended
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:509)
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:461)
at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1104)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:553)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:655)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:270)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:91)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:970)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666)
at oracle.jdbc.driver.T4CPreparedStatement.executeInternal(T4CPreparedStatement.java:1426)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3778)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1081)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
at org.sonar.server.platform.db.migration.step.UpsertImpl.execute(UpsertImpl.java:66)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.insertQualityProfileChange(RemoveOrphanRulesFromQualityProfiles.java:67)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.process(RemoveOrphanRulesFromQualityProfiles.java:51)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.lambda$execute$0(RemoveOrphanRulesFromQualityProfiles.java:47)
at org.sonar.server.platform.db.migration.step.SelectImpl.scroll(SelectImpl.java:78)
... 12 common frames omitted
Caused by: oracle.jdbc.OracleDatabaseException: ORA-00933: SQL command not properly ended
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:513)
... 32 common frames omitted
Have you tried also with the latest version available of ojdbc8 for 19C(19.18.0.0)?
This issue does not materialize in our environment using ojdbc11 and I am wondering if it can be related to the combination of versions here (DB + JDK + JDBC driver).
I will do some more tests on my side in order to reproduce the error in an environment closer to yours.
I haven’t tried ojdbc8 19.18.0.0, but instead I switched to ojdbc11 23.2.0.0. (Our old 9.9 LTS instance is now upgraded with this version and is running fine.) However, still the same issue. This time I changed the log level to TRACE to get more insight.
To summarize the combination of versions:
Red Hat Enterprise Linux Server release 7.9 (Maipo)
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.18.0.0.0
Oracle JDBC driver ojdbc11-23.2.0.0.jar
Oracle Java 17.0.6 2023-01-17 LTS, Java HotSpot™ 64-Bit Server VM (build 17.0.6+9-LTS-190, mixed mode, sharing)
In the log we can see the DEBUG message Executed rollback on connection oracle.jdbc.driver.T4CConnection@23475531 due to dirty commit state on close() after the INSERT statement. Could this be the issue?
Relevant part from web.log:
2023.04.14 10:58:50 INFO web[][DbMigrations] #100000 'Remove orphan rules in Quality Profiles'...
2023.04.14 10:58:50 TRACE web[][sql] time=23ms | sql=select ar.uuid, ar.profile_uuid, ar.rule_uuid from rules_profiles rp inner join active_rules ar on ar.profile_uuid = rp.uuid inner join rules r on r.uuid = ar.rule_uuid where rp.language != r.language
2023.04.14 10:58:50 TRACE web[][sql] time=21ms | sql=INSERT INTO qprofile_changes (kee, rules_profile_uuid, change_type, created_at, user_uuid, change_data) VALUES(?, ?, ?, ?, ?, ?); | params=AYd-_R7L0nJM1U2JLklQ, AX3iVkJEwiSjp8yPHWhr, DEACTIVATED, 1681462730444, [null], ruleUuid=5112
2023.04.14 10:58:50 DEBUG web[][c.z.h.p.ProxyConnection] HikariPool-1 - Executed rollback on connection oracle.jdbc.driver.T4CConnection@23475531 due to dirty commit state on close().
2023.04.14 10:58:50 DEBUG web[][c.z.h.pool.PoolBase] HikariPool-1 - Reset (autoCommit) on connection oracle.jdbc.driver.T4CConnection@23475531
2023.04.14 10:58:50 DEBUG web[][c.z.h.p.ProxyConnection] HikariPool-1 - Executed rollback on connection oracle.jdbc.driver.T4CConnection@58399d82 due to dirty commit state on close().
2023.04.14 10:58:50 DEBUG web[][c.z.h.pool.PoolBase] HikariPool-1 - Reset (autoCommit) on connection oracle.jdbc.driver.T4CConnection@58399d82
2023.04.14 10:58:50 ERROR web[][DbMigrations] #100000 'Remove orphan rules in Quality Profiles': failure | time=77ms
2023.04.14 10:58:50 ERROR web[][DbMigrations] Executed DB migrations: failure | time=78ms
2023.04.14 10:58:50 DEBUG web[][o.s.c.a.AnnotationConfigApplicationContext] Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@51350b18 , started on Fri Apr 14 10:58:50 CEST 2023, parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@30922f8d
2023.04.14 10:58:50 TRACE web[][o.s.c.p.PriorityBeanFactory] Returning cached instance of singleton bean 'lifecycleProcessor'
2023.04.14 10:58:50 TRACE web[][o.s.c.p.PriorityBeanFactory] Destroying singletons in org.sonar.core.platform.PriorityBeanFactory@7b634005 : defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,... <cut>
2023.04.14 10:58:50 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration failed | time=108ms
2023.04.14 10:58:50 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration ended with an exception
org.sonar.server.platform.db.migration.step.MigrationStepExecutionException: Execution of migration step #100000 'Remove orphan rules in Quality Profiles' failed
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:79)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:67)
at com.google.common.collect.ImmutableList.forEach(ImmutableList.java:422)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:52)
at org.sonar.server.platform.db.migration.engine.MigrationEngineImpl.execute(MigrationEngineImpl.java:54)
at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doUpgradeDb(DatabaseMigrationImpl.java:105)
at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doDatabaseMigration(DatabaseMigrationImpl.java:80)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.IllegalStateException: Error during processing of row: [uuid=AX3iVhstwiSjp8yPHWT4,profile_uuid=AX3iVkJEwiSjp8yPHWhr,rule_uuid=5112]
at org.sonar.server.platform.db.migration.step.SelectImpl.newExceptionWithRowDetails(SelectImpl.java:89)
at org.sonar.server.platform.db.migration.step.SelectImpl.scroll(SelectImpl.java:81)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.execute(RemoveOrphanRulesFromQualityProfiles.java:47)
at org.sonar.server.platform.db.migration.step.DataChange.execute(DataChange.java:44)
at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:75)
... 9 common frames omitted
Caused by: java.sql.SQLSyntaxErrorException: ORA-00933: SQL command not properly ended
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:702)
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:608)
at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1335)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:1041)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:443)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:533)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:262)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:1392)
at oracle.jdbc.driver.OracleStatement.executeSQLStatement(OracleStatement.java:1877)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1520)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3751)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:4180)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1015)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.sonar.db.profiling.InvocationUtils.invokeQuietly(InvocationUtils.java:34)
at org.sonar.db.profiling.ProfilingPreparedStatementHandler.invoke(ProfilingPreparedStatementHandler.java:45)
at jdk.proxy2/jdk.proxy2.$Proxy84.execute(Unknown Source)
at org.sonar.server.platform.db.migration.step.UpsertImpl.execute(UpsertImpl.java:66)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.insertQualityProfileChange(RemoveOrphanRulesFromQualityProfiles.java:67)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.process(RemoveOrphanRulesFromQualityProfiles.java:51)
at org.sonar.server.platform.db.migration.version.v100.RemoveOrphanRulesFromQualityProfiles.lambda$execute$0(RemoveOrphanRulesFromQualityProfiles.java:47)
at org.sonar.server.platform.db.migration.step.SelectImpl.scroll(SelectImpl.java:78)
... 12 common frames omitted
Caused by: oracle.jdbc.OracleDatabaseException: ORA-00933: SQL command not properly ended
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:710)
... 38 common frames omitted
Hello @dagbjorn I can confirm that there is an issue in the database migration that materializes with your Oracle setup when orphan rules are found in the database.
I created a Jira for keeping track of it and fix it in 10.1, here you can find all the details.
Thanks a lot for sharing the details that helped in identifying the issue.
