DependencyTrack / dependency-track

Dependency-Track is an intelligent Component Analysis platform that allows organizations to identify and reduce risk in the software supply chain.
https://dependencytrack.org/
Apache License 2.0
2.61k stars 552 forks source link

Error when listing project vulnerabilities #2845

Open Atrejoe opened 1 year ago

Atrejoe commented 1 year ago

Current Behavior

When requesting vuulnerabilities for an existing project, server responds with a 500 status code. Internal logging indicates a posisble DAL issue: Please note that this does not occur for all projects,

API Call url:

/v1/vulnerability/project/{uuid}

Error message:

...
Caused by: org.datanucleus.exceptions.NucleusDataStoreException: Cannot get Object result for param = 2 for column "COMPONENT.AUTHOR" : The conversion from varchar to CLOB is unsupported.
...

Full log:

2023-06-22T08:41:36.712164252Z javax.jdo.JDOUserException: Exception thrown while loading remaining rows of query
2023-06-22T08:41:36.712171053Z  at org.datanucleus.api.jdo.JDOAdapter.getUserExceptionForException(JDOAdapter.java:507)
2023-06-22T08:41:36.712185655Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult.closingConnection(ForwardQueryResult.java:304)
2023-06-22T08:41:36.712190856Z  at org.datanucleus.store.query.AbstractQueryResult.disconnect(AbstractQueryResult.java:106)
2023-06-22T08:41:36.712195657Z  at org.datanucleus.store.rdbms.query.AbstractRDBMSQueryResult.disconnect(AbstractRDBMSQueryResult.java:283)
2023-06-22T08:41:36.712200357Z  at org.datanucleus.store.rdbms.query.JDOQLQuery$1.managedConnectionPreClose(JDOQLQuery.java:746)
2023-06-22T08:41:36.712205058Z  at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.close(ConnectionFactoryImpl.java:527)
2023-06-22T08:41:36.712209658Z  at org.datanucleus.store.connection.AbstractManagedConnection.release(AbstractManagedConnection.java:92)
2023-06-22T08:41:36.712214559Z  at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.release(ConnectionFactoryImpl.java:366)
2023-06-22T08:41:36.712219460Z  at org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:821)
2023-06-22T08:41:36.712224160Z  at org.datanucleus.store.query.Query.executeQuery(Query.java:2004)
2023-06-22T08:41:36.712228761Z  at org.datanucleus.store.query.Query.executeWithArray(Query.java:1893)
2023-06-22T08:41:36.712233662Z  at org.datanucleus.api.jdo.JDOQuery.executeInternal(JDOQuery.java:433)
2023-06-22T08:41:36.712239662Z  at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:276)
2023-06-22T08:41:36.712244463Z  at org.dependencytrack.persistence.ComponentQueryManager.getAllComponents(ComponentQueryManager.java:130)
2023-06-22T08:41:36.712249164Z  at org.dependencytrack.persistence.QueryManager.getAllComponents(QueryManager.java:877)
2023-06-22T08:41:36.712253764Z  at org.dependencytrack.persistence.VulnerabilityQueryManager.getVulnerabilities(VulnerabilityQueryManager.java:426)
2023-06-22T08:41:36.712258465Z  at org.dependencytrack.persistence.QueryManager.getVulnerabilities(QueryManager.java:957)
2023-06-22T08:41:36.712263065Z  at org.dependencytrack.resources.v1.VulnerabilityResource.getVulnerabilitiesByProject(VulnerabilityResource.java:128)
2023-06-22T08:41:36.712267766Z  at jdk.internal.reflect.GeneratedMethodAccessor798.invoke(Unknown Source)
2023-06-22T08:41:36.712272367Z  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
2023-06-22T08:41:36.712278267Z  at java.base/java.lang.reflect.Method.invoke(Unknown Source)
2023-06-22T08:41:36.712282968Z  at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52)
2023-06-22T08:41:36.712287769Z  at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:134)
2023-06-22T08:41:36.712292469Z  at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:177)
2023-06-22T08:41:36.712301270Z  at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:176)
2023-06-22T08:41:36.712306371Z  at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:81)
2023-06-22T08:41:36.712311072Z  at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:478)
2023-06-22T08:41:36.712315672Z  at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:400)
2023-06-22T08:41:36.712320273Z  at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:81)
2023-06-22T08:41:36.712324874Z  at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:256)
2023-06-22T08:41:36.712329474Z  at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
2023-06-22T08:41:36.712334075Z  at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
2023-06-22T08:41:36.712338675Z  at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
2023-06-22T08:41:36.712343476Z  at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
2023-06-22T08:41:36.712347977Z  at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
2023-06-22T08:41:36.712352477Z  at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265)
2023-06-22T08:41:36.712357178Z  at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:235)
2023-06-22T08:41:36.712361778Z  at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:684)
2023-06-22T08:41:36.712366379Z  at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394)
2023-06-22T08:41:36.712371380Z  at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346)
2023-06-22T08:41:36.712375880Z  at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:358)
2023-06-22T08:41:36.712380781Z  at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:311)
2023-06-22T08:41:36.712385482Z  at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205)
2023-06-22T08:41:36.712389982Z  at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1419)
2023-06-22T08:41:36.712394583Z  at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:764)
2023-06-22T08:41:36.712399283Z  at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1665)
2023-06-22T08:41:36.712403984Z  at alpine.server.filters.ContentSecurityPolicyFilter.doFilter(ContentSecurityPolicyFilter.java:225)
2023-06-22T08:41:36.712408585Z  at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
2023-06-22T08:41:36.713265697Z  at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
2023-06-22T08:41:36.713283500Z  at alpine.server.filters.ClickjackingFilter.doFilter(ClickjackingFilter.java:93)
2023-06-22T08:41:36.713295501Z  at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
2023-06-22T08:41:36.713300602Z  at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
2023-06-22T08:41:36.713305302Z  at alpine.server.filters.WhitelistUrlFilter.doFilter(WhitelistUrlFilter.java:166)
2023-06-22T08:41:36.713310603Z  at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)
2023-06-22T08:41:36.713315504Z  at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
2023-06-22T08:41:36.713320104Z  at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
2023-06-22T08:41:36.713325005Z  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
2023-06-22T08:41:36.713329606Z  at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578)
2023-06-22T08:41:36.713334206Z  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
2023-06-22T08:41:36.713338807Z  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
2023-06-22T08:41:36.713343507Z  at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)
2023-06-22T08:41:36.713348308Z  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
2023-06-22T08:41:36.713352909Z  at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1385)
2023-06-22T08:41:36.713357609Z  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
2023-06-22T08:41:36.713362310Z  at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
2023-06-22T08:41:36.713367011Z  at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)
2023-06-22T08:41:36.713373111Z  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
2023-06-22T08:41:36.713378012Z  at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1307)
2023-06-22T08:41:36.713382713Z  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
2023-06-22T08:41:36.713387313Z  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
2023-06-22T08:41:36.713391914Z  at org.eclipse.jetty.server.Server.handle(Server.java:563)
2023-06-22T08:41:36.713396614Z  at org.eclipse.jetty.server.HttpChannel.lambda$handle$0(HttpChannel.java:505)
2023-06-22T08:41:36.713401215Z  at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:762)
2023-06-22T08:41:36.713405816Z  at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:497)
2023-06-22T08:41:36.713410416Z  at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
2023-06-22T08:41:36.713415017Z  at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
2023-06-22T08:41:36.713423818Z  at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
2023-06-22T08:41:36.713428619Z  at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
2023-06-22T08:41:36.713433519Z  at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)
2023-06-22T08:41:36.713438320Z  at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)
2023-06-22T08:41:36.713443221Z  at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)
2023-06-22T08:41:36.713448021Z  at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:140)
2023-06-22T08:41:36.713452722Z  at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
2023-06-22T08:41:36.713457522Z  at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:936)
2023-06-22T08:41:36.713462123Z  at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1080)
2023-06-22T08:41:36.713466924Z  at java.base/java.lang.Thread.run(Unknown Source)
2023-06-22T08:41:36.713471624Z Caused by: org.datanucleus.exceptions.NucleusDataStoreException: Cannot get Object result for param = 2 for column "COMPONENT.AUTHOR" : The conversion from varchar to CLOB is unsupported.
2023-06-22T08:41:36.714075304Z  at org.datanucleus.store.rdbms.mapping.column.ClobColumnMapping.getObject(ClobColumnMapping.java:147)
2023-06-22T08:41:36.714086005Z  at org.datanucleus.store.rdbms.mapping.column.ClobColumnMapping.getString(ClobColumnMapping.java:107)
2023-06-22T08:41:36.714091106Z  at org.datanucleus.store.rdbms.mapping.java.SingleFieldMapping.getString(SingleFieldMapping.java:208)
2023-06-22T08:41:36.714095806Z  at org.datanucleus.store.rdbms.fieldmanager.ResultSetGetter.fetchStringField(ResultSetGetter.java:133)
2023-06-22T08:41:36.714101007Z  at org.datanucleus.state.StateManagerImpl.replacingStringField(StateManagerImpl.java:2030)
2023-06-22T08:41:36.714106008Z  at org.dependencytrack.model.Component.dnReplaceField(Component.java)
2023-06-22T08:41:36.714111308Z  at org.dependencytrack.model.Component.dnReplaceFields(Component.java)
2023-06-22T08:41:36.714116309Z  at org.datanucleus.state.StateManagerImpl.replaceNonLoadedFields(StateManagerImpl.java:4393)
2023-06-22T08:41:36.714121410Z  at org.datanucleus.store.rdbms.query.PersistentClassROF$1.fetchNonLoadedFields(PersistentClassROF.java:601)
2023-06-22T08:41:36.714126410Z  at org.datanucleus.ExecutionContextImpl.findObject(ExecutionContextImpl.java:3106)
2023-06-22T08:41:36.714131311Z  at org.datanucleus.store.rdbms.query.PersistentClassROF.findObjectWithIdAndLoadFields(PersistentClassROF.java:521)
2023-06-22T08:41:36.714136212Z  at org.datanucleus.store.rdbms.query.PersistentClassROF.getObject(PersistentClassROF.java:425)
2023-06-22T08:41:36.714146913Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult.nextResultSetElement(ForwardQueryResult.java:181)
2023-06-22T08:41:36.714168916Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult$QueryResultIterator.next(ForwardQueryResult.java:410)
2023-06-22T08:41:36.714174017Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult.processNumberOfResults(ForwardQueryResult.java:137)
2023-06-22T08:41:36.714179017Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult.advanceToEndOfResultSet(ForwardQueryResult.java:165)
2023-06-22T08:41:36.714184318Z  at org.datanucleus.store.rdbms.query.ForwardQueryResult.closingConnection(ForwardQueryResult.java:292)
2023-06-22T08:41:36.714194019Z  ... 84 common frames omitted
2023-06-22T08:41:36.714198920Z Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The conversion from varchar to CLOB is unsupported.
2023-06-22T08:41:36.714204021Z  at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:237)
2023-06-22T08:41:36.714208921Z  at com.microsoft.sqlserver.jdbc.DataTypes.throwConversionError(DataTypes.java:1112)
2023-06-22T08:41:36.714214022Z  at com.microsoft.sqlserver.jdbc.ServerDTVImpl.getValue(dtv.java:3706)
2023-06-22T08:41:36.714218923Z  at com.microsoft.sqlserver.jdbc.DTV.getValue(dtv.java:247)
2023-06-22T08:41:36.714224623Z  at com.microsoft.sqlserver.jdbc.Column.getValue(Column.java:190)
2023-06-22T08:41:36.714229724Z  at com.microsoft.sqlserver.jdbc.SQLServerResultSet.getValue(SQLServerResultSet.java:2085)
2023-06-22T08:41:36.714234725Z  at com.microsoft.sqlserver.jdbc.SQLServerResultSet.getValue(SQLServerResultSet.java:2071)
2023-06-22T08:41:36.714240125Z  at com.microsoft.sqlserver.jdbc.SQLServerResultSet.getClob(SQLServerResultSet.java:2847)
2023-06-22T08:41:36.714245226Z  at com.zaxxer.hikari.pool.HikariProxyResultSet.getClob(HikariProxyResultSet.java)
2023-06-22T08:41:36.714250127Z  at org.datanucleus.store.rdbms.mapping.column.ClobColumnMapping.getObject(ClobColumnMapping.java:121)
2023-06-22T08:41:36.714255127Z  ... 100 common frames omitted

When looking at the code, I see a generic call to obtain all components based on model Component.java. In the model the attribute 'Author' is annotated with the RegexSequence > PRINTABLE_CHARS validation attribute, could this cause trouble? I do not understand the character classes yet, see also https://regex101.com/r/rPR9yM/1

The longest value in my database is 63 characters. Some have characters like @,-,,,..

Steps to Reproduce

  1. Call url above. As this appears to be a data/mappingproblems, I do not know the true cause yet.

Expected Behavior

Returns list of vulnerabilites

Dependency-Track Version

4.8.2

Dependency-Track Distribution

Container Image

Database Server

Microsoft SQL Server

Database Server Version

12

Browser

N/A

Checklist

nscuro commented 1 year ago

Please check the column type of "COMPONENT"."AUTHOR" in your database. It was changed from VARCHAR to TEXT in 4.8.0. The migration should have happened automatically when DT >= 4.8.0 was first started, but it appears like it's still VARCHAR in your case.

Atrejoe commented 1 year ago

Thanks for your prompt response; It's still varchar(255): image

This leaves a few questions, before manually changing it:

Atrejoe commented 1 year ago

Thanks for the hint, I have for now rudely changed the field, using:

alter table [dbo].[COMPONENT] alter column author text null

This alleviated the problem for my particular case/user, but does not resolve the issue: I do not know If I have missed something (other database changes, nullability, indices). When I know how to do this properly, I will revert this change and apply a true fix.

nscuro commented 1 year ago

DT executes migrations whenever it starts up. It compares the value in the SCHEMAVERSION table with its current version and executes all migrations until that version sequentially. If upgrades fail, the application should not even start.

Here's an example migration for v4.8.0, which included the type change of AUTHOR: https://github.com/DependencyTrack/dependency-track/blob/master/src/main/java/org/dependencytrack/upgrade/v480/v480Updater.java

You could check your logs for anything logged by UpgradeInitializer.

Atrejoe commented 1 year ago

Are you saying I'm missing v450,460,463,470 & 480, as I am on schema version 4.4.0?

Currently I'm running 4.8.2 as a backend: image

While the databases' schema still indicates 4.4.0: image

When looking in my docker output logs, I do not see UpgradeInitializer mentioned. Should I look elsewhere?

Compose setup:

volumes:
  dependency-track:

services:
  dtrack-apiserver:
    image: dependencytrack/apiserver:4.8.2
    environment:
    # Database Properties
    - ALPINE_DATABASE_MODE=external
    - ALPINE_DATABASE_URL=<!-- snip -->
    - ALPINE_DATABASE_DRIVER=com.microsoft.sqlserver.jdbc.SQLServerDriver
    - ALPINE_DATABASE_USERNAME=<!-- snip -->
    - ALPINE_DATABASE_PASSWORD=<!-- snip -->
    <!-- snip -->
    - LOGGING_LEVEL=Debug
    <!-- snip -->
    volumes:
      - 'dependency-track:/data'
    restart: unless-stopped
Atrejoe commented 1 year ago

While looking a bit harder, I actually found somethin possibly relevant, a failure in the v450 updater:

2023-06-23T08:43:56.027492905Z 2023-06-23 08:43:56,018 INFO [UpgradeInitializer] Initializing upgrade framework
2023-06-23T08:44:01.078659949Z 2023-06-23 08:44:01,077 DEBUG [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v400.v400Updater does not need to run.
2023-06-23T08:44:01.080072278Z 2023-06-23 08:44:01,079 DEBUG [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v410.v410Updater does not need to run.
2023-06-23T08:44:01.081196382Z 2023-06-23 08:44:01,081 DEBUG [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v420.v420Updater does not need to run.
2023-06-23T08:44:01.083420886Z 2023-06-23 08:44:01,083 DEBUG [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v440.v440Updater does not need to run.
2023-06-23T08:44:01.090408427Z 2023-06-23 08:44:01,090 INFO [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v450.v450Updater about to run.
2023-06-23T08:44:01.090464232Z 2023-06-23 08:44:01,090 INFO [v450Updater] Deleting NIST directory
2023-06-23T08:44:01.143203470Z 2023-06-23 08:44:01,142 INFO [v450Updater] Clearing vulnerability CWEs. CWEs will be recreated when vulnerabilities are next synchronized.
2023-06-23T08:44:29.717124905Z 2023-06-23 08:44:29,716 INFO [v450Updater] Creating VIEW_POLICY_VIOLATION permission
2023-06-23T08:44:29.747406999Z 2023-06-23 08:44:29,747 ERROR [UpgradeExecutor] Error in executing upgrade class: org.dependencytrack.upgrade.v450.v450Updater
2023-06-23T08:44:29.747444502Z com.microsoft.sqlserver.jdbc.SQLServerException: Violation of UNIQUE KEY constraint 'PERMISSION_IDX'. Cannot insert duplicate key in object 'dbo.PERMISSION'. The duplicate key value is (VIEW_POLICY_VIOLATION).
2023-06-23T08:44:29.747452503Z  at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:265)
2023-06-23T08:44:29.747458104Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1676)
2023-06-23T08:44:29.747463104Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:620)
2023-06-23T08:44:29.747468205Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:540)
2023-06-23T08:44:29.747472905Z  at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7620)
2023-06-23T08:44:29.747477606Z  at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3916)
2023-06-23T08:44:29.747482306Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:268)
2023-06-23T08:44:29.747487106Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:242)
2023-06-23T08:44:29.747491807Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:486)
2023-06-23T08:44:29.747496507Z  at org.datanucleus.store.rdbms.datasource.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
2023-06-23T08:44:29.747583715Z  at org.datanucleus.store.rdbms.datasource.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
2023-06-23T08:44:29.747593516Z  at org.dependencytrack.upgrade.v450.v450Updater.executeUpgrade(v450Updater.java:80)
2023-06-23T08:44:29.747608718Z  at alpine.server.upgrade.UpgradeExecutor.executeUpgrades(UpgradeExecutor.java:88)
2023-06-23T08:44:29.747613618Z  at org.dependencytrack.upgrade.UpgradeInitializer.contextInitialized(UpgradeInitializer.java:83)
2023-06-23T08:44:29.747618318Z  at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1050)
2023-06-23T08:44:29.747623019Z  at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624)
2023-06-23T08:44:29.747628919Z  at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:985)
2023-06-23T08:44:29.747633620Z  at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740)
2023-06-23T08:44:29.747638320Z  at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392)
2023-06-23T08:44:29.747642921Z  at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1304)
2023-06-23T08:44:29.747647521Z  at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:902)
2023-06-23T08:44:29.747652022Z  at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306)
2023-06-23T08:44:29.747656622Z  at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:532)
2023-06-23T08:44:29.747661222Z  at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93)
2023-06-23T08:44:29.747665823Z  at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171)
2023-06-23T08:44:29.747670423Z  at org.eclipse.jetty.server.Server.start(Server.java:470)
2023-06-23T08:44:29.747675024Z  at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
2023-06-23T08:44:29.747679624Z  at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89)
2023-06-23T08:44:29.747684225Z  at org.eclipse.jetty.server.Server.doStart(Server.java:415)
2023-06-23T08:44:29.747688725Z  at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93)
2023-06-23T08:44:29.747693325Z  at alpine.embedded.EmbeddedJettyServer.main(EmbeddedJettyServer.java:100)
2023-06-23T08:44:29.747698526Z 2023-06-23 08:44:29,747 ERROR [UpgradeInitializer] An error occurred performing upgrade processing. com.microsoft.sqlserver.jdbc.SQLServerException: Violation of UNIQUE KEY constraint 'PERMISSION_IDX'. Cannot insert duplicate key in object 'dbo.PERMISSION'. The duplicate key value is (VIEW_POLICY_VIOLATION).

Current content from dbo.Permission (spoiler , it actually contains VIEW_POLICY_VIOLATION)

ID DESCRIPTION NAME
1 Allows the ability to upload CycloneDX and SPDX Bill of Materials (BOM) BOM_UPLOAD
2 Provides the ability to view the portfolio of projects, components, and licenses VIEW_PORTFOLIO
3 Allows the creation, modification, and deletion of data in the portfolio PORTFOLIO_MANAGEMENT
4 Provides the ability to make analysis decisions on vulnerabilities VULNERABILITY_ANALYSIS
5 Provides the ability to make analysis decisions on policy violations POLICY_VIOLATION_ANALYSIS
6 Allows the management of users, teams, and API keys ACCESS_MANAGEMENT
7 Allows the configuration of the system including notifications, repositories, and email settings SYSTEM_CONFIGURATION
8 Provides the ability to optionally create project (if non-existent) on BOM or scan upload PROJECT_CREATION_UPLOAD
9 Allows the creation, modification, and deletion of policy POLICY_MANAGEMENT
22 Provides the ability to view policy violations VIEW_POLICY_VIOLATION
23 Allows management of internally-defined vulnerabilities VULNERABILITY_MANAGEMENT
37 Provides the ability to view the vulnerabilities projects are affected by VIEW_VULNERABILITY
Atrejoe commented 1 year ago

I do not know what caused the value to be there (manual intervention by my predessor, failing upgrade script in previous version op DTrack API or something else)

After I verified that the new permission was not in use (which were the subsequent steps in the 4.5.0 upgrade), I simply marked the existing permisison as obsolete and restarted. This triggered a successfull upgrade from DB Schema 4.4.0 to 4.7.0, then crashing on the 4.8.0 migration (Jira config migration):

2023-06-26T08:26:15.229303892Z 2023-06-26 08:26:15,229 INFO [UpgradeExecutor] Upgrade class org.dependencytrack.upgrade.v480.v480Updater about to run.
2023-06-26T08:26:15.229331495Z 2023-06-26 08:26:15,229 INFO [v480Updater] Changing JDBC type of "COMPONENT"."AUTHOR" from VARCHAR to CLOB
2023-06-26T08:26:15.343391761Z 2023-06-26 08:26:15,343 INFO [v480Updater] Setting Jira property values from Groupname 'jira' to Groupname 'integrations'
2023-06-26T08:26:15.472360499Z 2023-06-26 08:26:15,471 ERROR [UpgradeExecutor] Error in executing upgrade class: org.dependencytrack.upgrade.v480.v480Updater
2023-06-26T08:26:15.472418305Z com.microsoft.sqlserver.jdbc.SQLServerException: Violation of UNIQUE KEY constraint 'CONFIGPROPERTY_U1'. Cannot insert duplicate key in object 'dbo.CONFIGPROPERTY'. The duplicate key value is (integrations, jira.password).
2023-06-26T08:26:15.472433306Z  at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:265)
2023-06-26T08:26:15.472444107Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1676)
2023-06-26T08:26:15.472453408Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:620)
2023-06-26T08:26:15.472463109Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:540)
2023-06-26T08:26:15.472488012Z  at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7620)
2023-06-26T08:26:15.472521815Z  at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3916)
2023-06-26T08:26:15.472533916Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:268)
2023-06-26T08:26:15.472543117Z  at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:242)
2023-06-26T08:26:15.472552318Z  at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:486)
2023-06-26T08:26:15.472561419Z  at org.datanucleus.store.rdbms.datasource.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
2023-06-26T08:26:15.472570420Z  at org.datanucleus.store.rdbms.datasource.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
2023-06-26T08:26:15.472579521Z  at org.dependencytrack.upgrade.v480.v480Updater.setJiraPropertyValuesFromJiraToIntegrationGroup(v480Updater.java:72)
2023-06-26T08:26:15.472588522Z  at org.dependencytrack.upgrade.v480.v480Updater.executeUpgrade(v480Updater.java:41)
2023-06-26T08:26:15.472597322Z  at alpine.server.upgrade.UpgradeExecutor.executeUpgrades(UpgradeExecutor.java:88)
2023-06-26T08:26:15.472606323Z  at org.dependencytrack.upgrade.UpgradeInitializer.contextInitialized(UpgradeInitializer.java:83)
2023-06-26T08:26:15.472615324Z  at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:1050)
2023-06-26T08:26:15.472625725Z  at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:624)
2023-06-26T08:26:15.472634926Z  at org.eclipse.jetty.server.handler.ContextHandler.contextInitialized(ContextHandler.java:985)
2023-06-26T08:26:15.472643727Z  at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:740)
2023-06-26T08:26:15.472652528Z  at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:392)
2023-06-26T08:26:15.472661429Z  at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1304)
2023-06-26T08:26:15.472670230Z  at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:902)
2023-06-26T08:26:15.472679330Z  at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:306)
2023-06-26T08:26:15.472688331Z  at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:532)
2023-06-26T08:26:15.472697032Z  at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93)
2023-06-26T08:26:15.472705933Z  at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:171)
2023-06-26T08:26:15.472714934Z  at org.eclipse.jetty.server.Server.start(Server.java:470)
2023-06-26T08:26:15.472723735Z  at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114)
2023-06-26T08:26:15.472740236Z  at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:89)
2023-06-26T08:26:15.472749537Z  at org.eclipse.jetty.server.Server.doStart(Server.java:415)
2023-06-26T08:26:15.472758338Z  at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:93)
2023-06-26T08:26:15.472767239Z  at alpine.embedded.EmbeddedJettyServer.main(EmbeddedJettyServer.java:100)
2023-06-26T08:26:15.472781641Z 2023-06-26 08:26:15,472 ERROR [UpgradeInitializer] An error occurred performing upgrade processing. com.microsoft.sqlserver.jdbc.SQLServerException: Violation of UNIQUE KEY constraint 'CONFIGPROPERTY_U1'. Cannot insert duplicate key in object 'dbo.CONFIGPROPERTY'. The duplicate key value is (integrations, jira.password).

Again, no clue how these values got here, but I do see that the database migration is not transactional: upon failure the state of the database is mid-migration.

As I did not have any configured Jira integrations, I marked them too as obsolete, allowing them to be upgraded.

update [dbo].[CONFIGPROPERTY] 
set propertyname += '_obsolete'
where (GROUPNAME = 'integrations' and PROPERTYNAME like 'jira.%')

select *
from [dbo].[CONFIGPROPERTY]
where PROPERTYNAME like 'jira.%'

And voila, the database was migrated to 4.8.0 (being the most current) While all looks good now, I'm removing the obsolete records.