search

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.58k stars 542 forks source link

ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX" #582

Open msymons opened 4 years ago

msymons commented 4 years ago

Current Behavior:

Whilst performing issue triage (eg, attaching a comment in threat audit), there was a lack of system response followed by a 500 Error dialog.

Steps to Reproduce:

This incident occurrred just once so far.

Whilst performing triage of a threat I typed in a comment and attempted to save it... and nothing seemed to happen (comment was not saved).

I clicked save a couple of times and then attempted to set the status and attempted to suppress the threat. Nothing happened for either action.

The 500 error then popped up (although I cannot recall if it was straight away or as I tried to reload the screen or similar).

The logs show that there were multiple WARN events about constraint violations occurring due to a key already existing. I am guessing that my first attempt to save a comment actually did something and that the logged events relate to my subsequent clicks.

Expected Behavior:

Suggest that the system should provide dynamic feedback to inform the user that the request (button click) was accepted and is being processed.

Environment:

Additional Details:

2020-02-06 11:09:33,563 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: 737c8e22-7447-4360-b73c-689991ca8725
2020-02-06 11:09:40,040 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@2fcb54b6" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,040 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@e92b96e" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,040 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@e266c81" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,040 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@2d7da201" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,041 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,041 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,041 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@32ae0d92" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,041 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@283d1598" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,041 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,041 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,041 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,042 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,042 [] WARN [DataNucleus.Datastore.Persist] Insert of object "org.dependencytrack.model.Analysis@12562662" using statement "INSERT INTO "ANALYSIS" ("STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(367, 366, 66252) already exists.
2020-02-06 11:09:40,042 [] WARN [DataNucleus.General] ExecutionContext closed with active transaction, so rolling back the active transaction
2020-02-06 11:09:40,207 [] ERROR [DataNucleus.Transaction] Operation commit failed on resource: org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@548fc1b9, error code UNKNOWN and transaction [DataNucleus Transaction, ID=-1242486613-7547697, enlisted resources=[org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@548fc1b9]] : ERROR: update or delete on table "PROJECT" violates foreign key constraint "ANALYSIS_FK2" on table "ANALYSIS"
  Detail: Key (ID)=(367) is still referenced from table "ANALYSIS".
2020-02-06 11:09:58,641 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: 737c8e22-7447-4360-b73c-689991ca8725
stevespringett commented 4 years ago 
@Unique(name="ANALYSIS_COMPOSITE_IDX", members={"project", "component", "vulnerability"})

The logic in QueryManager and AnalysisResource seems fine. Will need to investigate further.

stevespringett commented 3 years ago

is this still an issue?

tomaszn commented 9 months ago

Yes, I see this in logs from today:

2023-11-27 14:03:04,472 INFO [UserResource] Successful OpenID Connect login / username: anonel.54321 / IP Address: 10.0.1.1 / User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36
2023-11-27 14:03:33,773 WARN [Persist] Insert of object "org.dependencytrack.model.Analysis@717be924" using statement "INSERT INTO "ANALYSIS" ("DETAILS","JUSTIFICATION","RESPONSE","STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(4068, 2202024, 296492) already exists.
2023-11-27 14:03:33,774 WARN [General] ExecutionContext closed with active transaction, so rolling back the active transaction
2023-11-27 14:03:33,780 ERROR [GlobalExceptionHandler] Uncaught internal server error
javax.jdo.JDODataStoreException: Insert of object "org.dependencytrack.model.Analysis@717be924" using statement "INSERT INTO "ANALYSIS" ("DETAILS","JUSTIFICATION","RESPONSE","STATE","COMPONENT_ID","PROJECT_ID","SUPPRESSED","VULNERABILITY_ID") VALUES (?,?,?,?,?,?,?,?)" failed : ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(4068, 2202024, 296492) already exists.
    at org.datanucleus.api.jdo.JDOAdapter.getJDOExceptionForNucleusException(JDOAdapter.java:605)
    at org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:702)
    at org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:722)
    at alpine.persistence.AbstractAlpineQueryManager.persist(AbstractAlpineQueryManager.java:427)
    at org.dependencytrack.persistence.FindingsQueryManager.makeAnalysis(FindingsQueryManager.java:209)
    at org.dependencytrack.persistence.QueryManager.makeAnalysis(QueryManager.java:1029)
    at org.dependencytrack.resources.v1.AnalysisResource.updateAnalysis(AnalysisResource.java:167)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:146)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:189)
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:176)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:93)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:478)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:400)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:81)
    at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:256)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265)
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:235)
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:684)
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394)
    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:358)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:311)
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205)
    at org.eclipse.jetty.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1419)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:764)
    at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1665)
    at alpine.server.filters.ContentSecurityPolicyFilter.doFilter(ContentSecurityPolicyFilter.java:225)
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
    at alpine.server.filters.ClickjackingFilter.doFilter(ClickjackingFilter.java:93)
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:202)
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
    at alpine.server.filters.WhitelistUrlFilter.doFilter(WhitelistUrlFilter.java:166)
    at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)
    at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:578)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1385)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1307)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
    at org.eclipse.jetty.server.Server.handle(Server.java:563)
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$0(HttpChannel.java:505)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:762)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:497)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:416)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:385)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:272)
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:140)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:936)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1080)
    at java.base/java.lang.Thread.run(Unknown Source)
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "ANALYSIS_COMPOSITE_IDX"
  Detail: Key ("PROJECT_ID", "COMPONENT_ID", "VULNERABILITY_ID")=(4068, 2202024, 296492) already exists.
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2713)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2401)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190)
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:152)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
    at org.datanucleus.store.rdbms.SQLController.executeStatementUpdate(SQLController.java:430)
    at org.datanucleus.store.rdbms.request.InsertRequest.execute(InsertRequest.java:520)
    at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObjectInTable(RDBMSPersistenceHandler.java:162)
    at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObject(RDBMSPersistenceHandler.java:138)
    at org.datanucleus.state.StateManagerImpl.internalMakePersistent(StateManagerImpl.java:4587)
    at org.datanucleus.state.StateManagerImpl.makePersistent(StateManagerImpl.java:4564)
    at org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2014)
    at org.datanucleus.ExecutionContext.persistObjectInternal(ExecutionContext.java:320)
    at org.datanucleus.ExecutionContextImpl.persistObjectWork(ExecutionContextImpl.java:1862)
    at org.datanucleus.ExecutionContextImpl.persistObject(ExecutionContextImpl.java:1723)
    at org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:697)
    ... 74 common frames omitted
nscuro commented 9 months ago

@tomaszn Is this reproducible or did it only happen once and then never again?

tomaszn commented 9 months ago

For this tuple of values it happened once. Last week it happened twice for other tuples.