search

VEuPathDB / EdaSubsettingService

A REST service to provide data and subsetting in the Exploratory Data Analysis Workspace
Apache License 2.0
0 stars 0 forks source link

Look into NPE for binary count endpoint #122

Open dmgaldi opened 9 months ago

dmgaldi commented 9 months ago 
"message": "500 Internal Server Error: POST [https://vectorbase.org/eda/studies/VBP_MEGA/entities/OBI_0000659/count\nTraceid:](https://vectorbase.org/eda/studies/VBP_MEGA/entities/OBI_0000659/count/nTraceid:)7c2cb8fe253344d188c851008c748683\n\n{\"status\":\"server-error\",\"message\":\"Error when producing count for entity OBI_0000659 for study VBP_MEGA\",\"requestId\":\"xkhswkNSpczQd7Ss25HtY\"}"
dmgaldi commented 9 months ago

Looked into this, but unable to reproduce yet. We should log the filters used in the future. It’s possibly a race condition. The DualBufferBinaryRecordReaer binary data stream that’s not supposed to ever return null is returning null when it’s not supposed to.

dmgaldi commented 8 months ago

We have an instance now with filters logged for VBP_MEGA:

[{"entityId":"EUPATH_0000605","type":"stringSet","variableId":"POPBIO_8000215","stringSet":["VBP0000844"]},{"entityId":"OBI_0000659","type":"numberRange","variableId":"OBI_0002988","min":1,"max":1}]
dmgaldi commented 8 months ago

Full array index out of bounds exception:

ESC[m java.lang.RuntimeException: Failed to write result
        at org.veupathdb.service.eda.ss.model.db.FilteredResultFactory.produceTabularSubsetFromFile(FilteredResultFactory.java:214) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.service.StudiesService.lambda$handleTabularRequest$7(StudiesService.java:291) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.generated.model.EntityTabularPostResponseStream.write(EntityTabularPostResponseStream.java:21) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:55) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:37) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:242) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:227) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:85) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:61) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.veupathdb.lib.container.jaxrs.server.middleware.PrometheusFilter.aroundWriteTo(PrometheusFilter.java:135) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.veupathdb.lib.container.jaxrs.server.middleware.RequestIdFilter.aroundWriteTo(RequestIdFilter.java:70) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1116) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:677) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:385) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:375) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:264) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:292) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:274) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:244) [service.jar:3.9.0]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:240) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:697) [service.jar:3.9.0]
        at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:367) [service.jar:3.9.0]
        at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:190) [service.jar:3.9.0]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535) [service.jar:3.9.0]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515) [service.jar:3.9.0]
        at java.lang.Thread.run(Thread.java:831) [?:?]
Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 3 out of bounds for length 3
        at org.veupathdb.service.eda.ss.Utils.trimPaddedBinary(Utils.java:28) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.BinaryValuesStreamer.lambda$streamIdValueBinaryPairs$1(BinaryValuesStreamer.java:106) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.FilteredValueIterator.nextMatch(FilteredValueIterator.java:91) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.FilteredValueIterator.next(FilteredValueIterator.java:78) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.FormattedTabularRecordStreamer$ValueStream.next(FormattedTabularRecordStreamer.java:124) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.FormattedTabularRecordStreamer.next(FormattedTabularRecordStreamer.java:76) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.db.FilteredResultFactory.produceTabularSubsetFromFile(FilteredResultFactory.java:201) ~[service.jar:3.9.0]
        ... 33 more
dmgaldi commented 8 months ago

NPE full stack trace:

ESC[m java.lang.NullPointerException: Cannot invoke "org.veupathdb.service.eda.ss.model.variable.VariableValueIdPair.getValue()" because "valuePair" is null
        at org.veupathdb.service.eda.ss.model.reducer.FilteredValueIterator.nextMatch(FilteredValueIterator.java:90) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.FilteredValueIterator.next(FilteredValueIterator.java:78) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.ancestor.AncestorExpander.advanceStreamsUntilIntersect(AncestorExpander.java:92) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.ancestor.AncestorExpander.nextMatch(AncestorExpander.java:79) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.ancestor.AncestorExpander.initialize(AncestorExpander.java:61) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.ancestor.AncestorExpander.hasNext(AncestorExpander.java:37) ~[service.jar:3.9.0]
        at java.util.stream.MatchOps$1MatchSink.accept(MatchOps.java:90) ~[?:?]
        at java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1602) ~[?:?]
        at java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:129) ~[?:?]
        at java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:502) ~[?:?]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:488) ~[?:?]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[?:?]
        at java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:230) ~[?:?]
        at java.util.stream.MatchOps$MatchOp.evaluateSequential(MatchOps.java:196) ~[?:?]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
        at java.util.stream.ReferencePipeline.allMatch(ReferencePipeline.java:637) ~[?:?]
        at org.veupathdb.service.eda.ss.model.reducer.StreamIntersectMerger.<init>(StreamIntersectMerger.java:30) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.reducer.DataFlowTreeReducer.reduce(DataFlowTreeReducer.java:61) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.model.db.FilteredResultFactory.produceTabularSubsetFromFile(FilteredResultFactory.java:177) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.ss.service.StudiesService.lambda$handleTabularRequest$7(StudiesService.java:291) ~[service.jar:3.9.0]
        at org.veupathdb.service.eda.generated.model.EntityTabularPostResponseStream.write(EntityTabularPostResponseStream.java:21) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:55) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:37) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.invokeWriteTo(WriterInterceptorExecutor.java:242) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor.aroundWriteTo(WriterInterceptorExecutor.java:227) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor.aroundWriteTo(JsonWithPaddingInterceptor.java:85) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor.aroundWriteTo(MappableExceptionWrapperInterceptor.java:61) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.veupathdb.lib.container.jaxrs.server.middleware.PrometheusFilter.aroundWriteTo(PrometheusFilter.java:135) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.veupathdb.lib.container.jaxrs.server.middleware.RequestIdFilter.aroundWriteTo(RequestIdFilter.java:70) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.WriterInterceptorExecutor.proceed(WriterInterceptorExecutor.java:139) ~[service.jar:3.9.0]
        at org.glassfish.jersey.message.internal.MessageBodyFactory.writeTo(MessageBodyFactory.java:1116) ~[service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:677) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:385) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:375) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:264) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:292) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:274) [service.jar:3.9.0]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:244) [service.jar:3.9.0]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:240) [service.jar:3.9.0]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:697) [service.jar:3.9.0]
        at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:367) [service.jar:3.9.0]
        at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:190) [service.jar:3.9.0]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:535) [service.jar:3.9.0]
        at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:515) [service.jar:3.9.0]
        at java.lang.Thread.run(Thread.java:831) [?:?]
dmgaldi commented 8 months ago

This seems to be fixed by https://github.com/VEuPathDB/FgpUtil/pull/28

The issue was the following from Object.wait()

A thread can wake up without being notified, interrupted, or timing out, a so-called spurious wakeup. While this will rarely occur in practice, applications must guard against it by testing for the condition that should have caused the thread to be awakened, and continuing to wait if the condition is not satisfied.

The bug was triggered when we were waiting for deserialized elements to become available but the thread was waking spuriously. Changing the if condition to a while condition seems to have fixed it.