Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

404 for components when opening project page #2315

Closed
2 tasks done
mphilipps opened this issue Dec 20, 2022 · 8 comments · Fixed by #3357
Closed
2 tasks done

404 for components when opening project page #2315

mphilipps opened this issue Dec 20, 2022 · 8 comments · Fixed by #3357
Labels
defect Something isn't working p2 Non-critical bugs, and features that help organizations to identify and reduce risk pending release

Comments

@mphilipps
Copy link

Current Behavior

hi,
After successfully uploading a BOM through the Jenkins plugin, the project page in the frontend throws a few http 404 errors for some of the components.

The requests themself look like this: api/v1/component/<UUID> with <UUID> being seemingly random, but persistent between requests of project page. The UUIDs don't show up in the COMPONENT table of the database.

When opening the project page and triggering the 404s nothing is being logged in the api servers docker log. The projects themself are written in javascript and have a large number of components (~1000).

In one case a coworker was able to fix the issue by manually downloading the BOM through the frontend.

Steps to Reproduce

  1. upload BOM
  2. open project page in the frontend

Expected Behavior

NO API errors

Dependency-Track Version

4.7.0

Dependency-Track Distribution

Container Image

Database Server

PostgreSQL

Database Server Version

13.9

Browser

Mozilla Firefox

Checklist

@mphilipps mphilipps added defect Something isn't working in triage labels Dec 20, 2022
@rkg-mm
Copy link
Contributor

rkg-mm commented Dec 20, 2022

We noticed this also before when we worked on the dependency-tree. In our case it always happened when some kind of error disrupted the BOM processing, which sometimes lead to the "directDependencies" field of a project not being updated when a BOM was processed. If the BOM contained less components than the one before, the directDependencies had still references to no longer existing elements. This was the case already in 4.6.x, but only happens in very special conditions from what we saw. we couldn't really find the root cause or a suitable fix in the short analysis we did.

I think this is the same problem.
Can you check for any errors during last BOM processing of that project?

@mphilipps
Copy link
Author

mphilipps commented Dec 20, 2022

After first encountering the issue I tried updating dependency track and restarted the docker containers for that. I don't think the logs are persistent, so I can't check them now, but I don't remember seeing any. We changed the tool for generating the BOM, which certainly could explain one or two dependencies disappearing, or getting tracked under a different name/id.

I just triggered the CI job again for the first project that got 'fixed' by downloading the BOM and I see some errors in the apiserver log, but no 404 requests.

2022-12-20 13:26:32,376 ERROR [LoggableUncaughtExceptionHandler] An unknown error occurred in an asynchronous event or notification thread                   
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2022-12-20T11:59:00.109987355Z, (lock=NativeFSLock(path=/data
/.dependency-track/index/project/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2022-12-20T08:59:00.149189807Z))
        at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191)                                                
        at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43)                                       
        at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43)                                                   
        at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121)                                 
        at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130)                           
        at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141)                                    
        at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48)                                                 
        at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55)                                                          
        at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452)                                                     
        at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488)                                                       
        at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208)                                               
        at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415)                                                                 
        at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471)                                                                        
        at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1757)                                                                         
        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1400)                                                                            
        at org.dependencytrack.search.ProjectIndexer.add(ProjectIndexer.java:90)
        at org.dependencytrack.search.ProjectIndexer.add(ProjectIndexer.java:43)
        at org.dependencytrack.tasks.IndexTask.inform(IndexTask.java:61)
        at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:101)
        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)
2022-12-20 13:26:35,382 ERROR [LoggableUncaughtExceptionHandler] An unknown error occurred in an asynchronous event or notification thread                   
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2022-12-20T11:59:00.117987344Z, (lock=NativeFSLock(path=/data
/.dependency-track/index/component/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2022-12-20T08:59:00.349189521Z
))                                                                                                                                                           
        at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191)                                                
        at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43)                                       
        at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43)                                                   
        at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121)                                 
        at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130)                           
        at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141)                                    
        at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48)                                                 
        at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55)                                                          
        at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452)                                                     
        at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488)                                                       
        at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208)                                               
        at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415)                                                                 
        at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471)                                                                        
        at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1757)                                                                         
        at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1400)                                                                            
        at org.dependencytrack.search.ComponentIndexer.add(ComponentIndexer.java:80)                                                                         
        at org.dependencytrack.search.ComponentIndexer.add(ComponentIndexer.java:44)                                                                         
        at org.dependencytrack.tasks.IndexTask.inform(IndexTask.java:58)                                                                                     
        at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:101)                                                               
        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)                                                                                                    
2022-12-20 13:26:42,602 INFO [BomUploadProcessingTask] Identified 0 new components
2022-12-20 13:26:42,603 INFO [BomUploadProcessingTask] Processing CycloneDX dependency graph for project: 3d5b5fc7-d8b5-42d1-9219-d7326920587d
2022-12-20 13:26:42,668 INFO [BomUploadProcessingTask] Processed 1159 components and 0 services uploaded to project 3d5b5fc7-d8b5-42d1-9219-d7326920587d
2022-12-20 13:26:42,669 INFO [RepositoryMetaAnalyzerTask] Performing component repository metadata analysis against 1159 components
2022-12-20 13:26:42,723 ERROR [LoggableUncaughtExceptionHandler] An unknown error occurred in an asynchronous event or notification thread
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2022-12-20T11:59:00.117987344Z, (lock=NativeFSLock(path=/data
/.dependency-track/index/servicecomponent/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2022-12-20T08:59:00.585
189184Z))
        at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191)
        at org.apache.lucene.store.LockValidatingDirectoryWrapper.syncMetaData(LockValidatingDirectoryWrapper.java:61)
        at org.apache.lucene.index.SegmentInfos.prepareCommit(SegmentInfos.java:802)
        at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:5084)
        at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3460)
        at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3770)
        at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3728)
        at org.dependencytrack.search.IndexManager.commit(IndexManager.java:249)
        at org.dependencytrack.tasks.IndexTask.inform(IndexTask.java:65)
        at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:101)
        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)

If this doesn't help I will see whether I can reproduce the two BOMs that triggered the bug when uploaded in successive order.

E:
Found the dependency-track.log file and there was no error when processing the BOM yesterday that triggered the 404/missing components issue.

@msymons
Copy link
Member

msymons commented Dec 20, 2022

If the BOM contained less components than the one before, the directDependencies had still references to no longer existing elements.

This is something that would happen a LOT in practice, especially in projects in DT that are used to track work in progress. In fact, the disappearance of components between one BOM upload and the next can be argued to show that DT is proving to be useful!

Just today we had one project where a (vulnerable) component vanished from the BOM because the vulnerability in DT drew attention to the presence of the component... and the solution was to exclude it from the POM because it simply was not needed.

@rkg-mm
Copy link
Contributor

rkg-mm commented Dec 20, 2022

This is something that would happen a LOT in practice, especially in projects in DT that are used to track work in progress.

Yes, but it only appears to be a problem (in the case we saw) if the BOM upload produced an error during processing. Because the directDependencies are updated last and if anything fails before it just doesn't happen, even though components might be deleted by processing step already. So if everything works fine there shouldn't be an issue.
Except that @mphilipps reports to see no error in one upload. Not sure if the errors shown in his post might be related to processing, that could explain it for this case at least then.

Someone with a bit deeper knowledge of the processing should look into this. Fact is, in some cases the directDependency field is out of sync.

@victorazzam
Copy link

We currently generate SBOMs with CycloneDX and upload them to Dependency Track using a cron job. Without running into any errors on the backend, we still often see missing components giving a 404 in the UI. Seven months later, are there any prospects for a fix (e.g. avoiding rendering components that don't exist)?

@corvusmod
Copy link

Hi

Same problem here. SBOM was correctly created and uploaded correctly. No errors in logs, but in some cases with random projects, when showing project information, the same 404 errors trying to get api/v1/component/?includeRepositoryMetaData=true

@nscuro
Copy link
Member

nscuro commented Jan 10, 2024

I think this issue was caused due to the fact that the dependency graph is processed before components are "reconciled" (i.e. components found to no longer be present in the project are removed). So theoretically, it could happen that components are removed that are referenced as "direct dependency" by others.

I am not 100% certain how this can be reproduced, but I am very optimistic that it's going to be resolved by #3357. The dependency graph is now processed last, so there's a less likely chance of this scenario happening. For each entry in the graph, we check if the component actually exists.

Also, the entire operation is now atomic, so even if BOM processing fails halfway, it will not cause an inconsistent state to be left behind.

@nscuro nscuro added p2 Non-critical bugs, and features that help organizations to identify and reduce risk and removed in triage labels Jan 10, 2024
Copy link
Contributor

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Mar 26, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
defect Something isn't working p2 Non-critical bugs, and features that help organizations to identify and reduce risk pending release
Projects
None yet
6 participants