Deleted projects still returned by search api

[IanBUK]

Ive got Dependency Track v 4.4.2 set up with a MySQL db, and have been round a loop of importing projects and then deleting them - both vis the api. This has been in attempting to work out a parent/child relationship. Now, when I search with the API for a project, I get all the deleted instances - as shown by their UUIDs. For example, create projectX, version 1.0, 1.2 and 1.3. via the api. Next delete them via the api. Now, add them again via the api. Now, search for projectX via the api. I get six records, two for each version, each with different UUIDs. If I call GetProject with these UUIDs, I get a "project not found" error, and if I use the console, they're not shown.

[stevespringett]

Thanks for reporting. Are there any errors in the logs?

[stevespringett]

Sounds like a possible defect.

[IanBUK]

Which logs should I ask our IT team to send me?

Further information:
I issued the following curl command:
curl "https://DEPENDENCY_TRACK_API_URL/api/v1/search/project?query=VERSION" -H "X-Api-Key: TOKEN"

The results were as follows:
{"results":{"project":[{"name":"PRODUCTNAME (OEM)","uuid":"757923f1-99c1-442d-87a8-6fab5c3b25d0","version":"VERSION"},{"name":"PRODUCTNAME","uuid":"34fd2ffa-3cb4-40dd-80fb-916448f59879","version":"VERSION"}]}}
Yet, when I go into the DependencyTrack console and search by VERSION, I get a single result with the uuid 117951db-c218-498e-a1a6-d7caaea7517a.

In the results, the two items show different names. This is due to me trying to clarify which distinct product - all under the same name but built specifically for different OEMs - in the project list. The first import just showed 650 items all called PRODUCTNAME. I deleted them and tried with PRODUCTNAME (OEM), which seems to help.

However, I was also trying to get my import to detect the first PRODUCTNAME (OEM) and add the one I was about to import as a child project. This was after trying to detect PRODUCTNAME (OEM) and issue an update to provide a new VERSION and sBom.

[IanBUK]

I guess one thing that would be wonderful would be a script to clear all the projects and metrics in the MySQL db and then do a single 'correct' import.

[IanBUK]

Some 'interesting' things in the dptrack_apiserver.log file:

2022-05-09 15:10:48,889 INFO [MetricsUpdateTask] Executing metrics update for project: 2b687196-4fa2-4b82-900a-3771b7c02864 2022-05-09 15:10:54,779 ERROR [VulnerabilityAnalysisTask] An unexpected error occurred performing a vulnerability analysis task javax.jdo.JDOObjectNotFoundException: No such database row at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:563) at org.datanucleus.api.jdo.JDOPersistenceManager.getObjectById(JDOPersistenceManager.java:1747) at alpine.persistence.AbstractAlpineQueryManager.detach(AbstractAlpineQueryManager.java:488) at org.dependencytrack.util.NotificationUtil.analyzeNotificationCriteria(NotificationUtil.java:63) at org.dependencytrack.tasks.scanners.BaseComponentAnalyzerTask.applyAnalysisFromCache(BaseComponentAnalyzerTask.java:97) at org.dependencytrack.tasks.scanners.OssIndexAnalysisTask.analyze(OssIndexAnalysisTask.java:161) at org.dependencytrack.tasks.scanners.OssIndexAnalysisTask.inform(OssIndexAnalysisTask.java:109) at org.dependencytrack.tasks.VulnerabilityAnalysisTask.performAnalysis(VulnerabilityAnalysisTask.java:151) at org.dependencytrack.tasks.VulnerabilityAnalysisTask.analyzeComponents(VulnerabilityAnalysisTask.java:117) at org.dependencytrack.tasks.VulnerabilityAnalysisTask.inform(VulnerabilityAnalysisTask.java:69) at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:99) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.base/java.lang.Thread.run(Unknown Source) Caused by: org.datanucleus.exceptions.NucleusObjectNotFoundException: No such database row at org.datanucleus.store.rdbms.request.FetchRequest.execute(FetchRequest.java:439) at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.fetchObject(RDBMSPersistenceHandler.java:316) at org.datanucleus.state.StateManagerImpl.loadFieldsFromDatastore(StateManagerImpl.java:1542) at org.datanucleus.state.StateManagerImpl.validate(StateManagerImpl.java:5521) at org.datanucleus.ExecutionContextImpl.findObject(ExecutionContextImpl.java:3562) at org.datanucleus.ExecutionContextImpl.findObject(ExecutionContextImpl.java:3021) at org.datanucleus.api.jdo.JDOPersistenceManager.getObjectById(JDOPersistenceManager.java:1742) ... 12 common frames omitted
First occurred on 9th May, occurs many times mainly whilst deleting all the projects via the API.

Then, from 3:21pm on 9th May I see many, many of:
2022-05-09 15:21:03,310 WARN [Persist] Delete of object "org.dependencytrack.model.Component@7307bec3" using statement "DELETE FROM "COMPONENT" WHERE "ID"=?" failed : Cannot delete or update a parent row: a foreign key constraint fails ("DependencyTrack"."DEPENDENCYMETRICS", CONSTRAINT "DEPENDENCYMETRICS_FK1" FOREIGN KEY ("COMPONENT_ID") REFERENCES "COMPONENT" ("ID"))
Then, this morning, there's a bunch of
2022-05-11 07:48:44,066 ERROR [Cache] >> EC.preCommit L1Cache op IS NULL!

Does this point to anything?

[stevespringett]

Does this point to anything?

Yes, likely a performance issue on the DT server. It appears that there's a backlog of components being analyzed and hasn't been able to keep up. As a result, when project deletion is requested, its failing due to components in that project being in the queue for being analyzed.

Some of this will get better with 4.5 and further improvements in 4.6, but optimizing the type of host DT is running on along with optimizing the database instance can go a long way.

Because of this, I'd recommend deletion from the database directlt.

[IanBUK]

OK, thanks for that update.

In my earlier comment, #1605 (comment), I included the output of the API, including a uuid of 757923f1-99c1-442d-87a8-6fab5c3b25d0. I've cloned the github repo and our IT people have given me a copy of the DB.

That uuid is not in the db, but the api still returns it.

I've perused the code and it seems to refer to an indexing service. What is this? Is it possible that I've stuffed the index server somehow and need to refresh it? Is the api not going directly to the db but some sort of index that I've managed to break?

[nscuro]

Good observation! DT uses Lucene for searches. It's file-based, the indexes are located at /data/.dependency-track/index/ (assuming you've deployed DT as container). To resolve the current situation, delete the index directory and restart DT. Indexes will be recreated on startup.

As far as the actual problem goes: Modifications to the index must be committed in order to take effect. It looks like project deletions are currently written to the index, but never committed. I'll submit a PR for this.

Another issue is that operations on the index are performed asynchronously in a thread pool of size 1. I think this is done to avoid race conditions. However, the same thread is also busy with mirroring the NVD (and in v4.5.0 EPSS as well). This means index operations are delayed until NVD mirroring is completed, which can take a rather long time, depending on your internet connection and CPU/RAM.

[IanBUK]

Ok, thanks for the suggestion. I’ll give it a go in the morning and update you on the results.

…

On 11 May 2022, at 20:00, Niklas ***@***.***> wrote:  Good observation! DT uses Lucene for searches. It's file-based, the indexes are located at /data/.dependency-track/index/ (assuming you've deployed DT as container). To resolve the current situation, delete the index directory and restart DT. Indexes will be recreated on startup. As far as the actual problem goes: Modifications to the index must be committed in order to take effect. It looks like project deletions are currently written to the index, but never committed. I'll submit a PR for this. Another issue is that operations on the index are performed asynchronously in a thread pool of size 1. I think this is done to avoid race conditions. However, the same thread is also busy with mirroring the NVD (and in v4.5.0 EPSS as well). This means index operations are delayed until NVD mirroring is completed, which can take a rather long time, depending on your internet connection and CPU/RAM. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.

[IanBUK]

" To resolve the current situation, delete the index directory and restart DT. Indexes will be recreated on startup."

This appears to have worked. Thanks for your help - and for responding so quickly.

[nscuro]

@IanBUK Thank you for reporting! :)
The actual problem that causes these situations should be resolved in 4.5.0, which is to be released very soon.

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.