Open officerNordberg opened 1 year ago
Here's what appears to be evidence of the indexer lock getting held making it grow stale until DT is restarted. Already Closed Exception followed by a manual reindex event that is skipped because the lock already exists.
dtrack-apiserver_1 | 2023-09-05 14:03:18,831 ERROR [LoggableUncaughtExceptionHandler] An unknown error occurred in an asynchronous event or notification thread
dtrack-apiserver_1 | org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2023-09-05T12:53:04.425997013Z, (lock=NativeFSLock(path=/data/.dependency-track/index/project/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2023-09-05T00:53:04.425799788Z))
dtrack-apiserver_1 | at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191)
dtrack-apiserver_1 | at org.apache.lucene.store.LockValidatingDirectoryWrapper.createOutput(LockValidatingDirectoryWrapper.java:43)
dtrack-apiserver_1 | at org.apache.lucene.store.TrackingDirectoryWrapper.createOutput(TrackingDirectoryWrapper.java:43)
dtrack-apiserver_1 | at org.apache.lucene.codecs.compressing.CompressingStoredFieldsWriter.<init>(CompressingStoredFieldsWriter.java:121)
dtrack-apiserver_1 | at org.apache.lucene.codecs.compressing.CompressingStoredFieldsFormat.fieldsWriter(CompressingStoredFieldsFormat.java:130)
dtrack-apiserver_1 | at org.apache.lucene.codecs.lucene87.Lucene87StoredFieldsFormat.fieldsWriter(Lucene87StoredFieldsFormat.java:141)
dtrack-apiserver_1 | at org.apache.lucene.index.StoredFieldsConsumer.initStoredFieldsWriter(StoredFieldsConsumer.java:48)
dtrack-apiserver_1 | at org.apache.lucene.index.StoredFieldsConsumer.startDocument(StoredFieldsConsumer.java:55)
dtrack-apiserver_1 | at org.apache.lucene.index.DefaultIndexingChain.startStoredFields(DefaultIndexingChain.java:452)
dtrack-apiserver_1 | at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:488)
dtrack-apiserver_1 | at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:208)
dtrack-apiserver_1 | at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415)
dtrack-apiserver_1 | at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471)
dtrack-apiserver_1 | at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1757)
dtrack-apiserver_1 | at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1400)
dtrack-apiserver_1 | at org.dependencytrack.search.ProjectIndexer.add(ProjectIndexer.java:90)
dtrack-apiserver_1 | at org.dependencytrack.search.ProjectIndexer.add(ProjectIndexer.java:43)
dtrack-apiserver_1 | at org.dependencytrack.tasks.IndexTask.inform(IndexTask.java:61)
dtrack-apiserver_1 | at alpine.event.framework.BaseEventService.lambda$publish$0(BaseEventService.java:101)
dtrack-apiserver_1 | at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
dtrack-apiserver_1 | at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
dtrack-apiserver_1 | at java.base/java.lang.Thread.run(Unknown Source)
dtrack-apiserver_1 | 2023-09-05 14:03:52,888 INFO [PolicyEngine] Evaluating 503 component(s) against applicable policies
dtrack-apiserver_1 | 2023-09-05 14:03:53,821 INFO [PolicyEngine] Policy analysis complete
dtrack-apiserver_1 | 2023-09-05 14:03:53,822 INFO [ProjectMetricsUpdateTask] Executing metrics update for project 9c2f806f-a07b-4d33-9d0f-846b46cc2d32
dtrack-apiserver_1 | 2023-09-05 14:03:55,924 INFO [ProjectMetricsUpdateTask] Completed metrics update for project 9c2f806f-a07b-4d33-9d0f-846b46cc2d32 in 00:02:102
dtrack-apiserver_1 | 2023-09-05 14:19:16,017 WARN [WebComponent] A servlet request to the URI https://local-dtrack-domain/api/v1/search/reindex?type=PROJECT contains form parameters in the request body but the request body has been consumed by the servlet or a servlet filter accessing the request parameters. Only resource methods using @FormParam will work as expected. Resource methods consuming the request body by other means will not work as expected.
dtrack-apiserver_1 | 2023-09-05 14:19:16,032 INFO [EventService] An singleton event (IndexEvent) was received but another singleton event of the same type is already in progress. Skipping.
@officerNordberg Just to be sure, is this still happening with the latest DT version? I remember addressing this issue with #2379.
This looks promising. If there is not already active work being done to implement this, I could have my.arm twisted to do so.
Originally posted by @nscuro in https://github.com/DependencyTrack/dependency-track/issues/1929#issuecomment-1703789226