search

deephaven / deephaven-core

Deephaven Community Core
Other
257 stars 80 forks source link

SessionState.ExportObject cancels should not make it to the log #4173

Closed nbauernfeind closed 1 year ago

nbauernfeind commented 1 year ago

Not sure exactly how to reproduce, but something is logging CANCEL status runtime exceptions when it's probably OK to not log at all.

io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Export in state CANCELLED
        at io.grpc.Status.asRuntimeException(Status.java:539)
        at io.grpc.protobuf.StatusProto.toStatusRuntimeException(StatusProto.java:52)
        at io.deephaven.proto.util.Exceptions.statusRuntimeException(Exceptions.java:14)
        at io.deephaven.server.session.SessionState$ExportBuilder.lambda$onErrorHandler$0(SessionState.java:1323)
        at io.deephaven.server.session.SessionState$ExportObject.setState(SessionState.java:799)
        at io.deephaven.server.session.SessionState$ExportObject.cancel(SessionState.java:1038)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller$SubscriptionRequestHandler.close(ArrowFlightUtil.java:695)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller.close(ArrowFlightUtil.java:422)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller.tryClose(ArrowFlightUtil.java:433)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller.onCancel(ArrowFlightUtil.java:395)
        at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onCancel(ServerCalls.java:195)
        at io.grpc.PartialForwardingServerCallListener.onCancel(PartialForwardingServerCallListener.java:40)
        at io.grpc.ForwardingServerCallListener.onCancel(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onCancel(ForwardingServerCallListener.java:40)
        at io.grpc.Contexts$ContextualizedServerCallListener.onCancel(Contexts.java:96)
        at io.grpc.PartialForwardingServerCallListener.onCancel(PartialForwardingServerCallListener.java:40)
        at io.grpc.ForwardingServerCallListener.onCancel(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onCancel(ForwardingServerCallListener.java:40)
        at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.lambda$onCancel$2(SessionServiceGrpcImpl.java:392)
        at io.deephaven.server.session.SessionServiceGrpcImpl.rpcWrapper(SessionServiceGrpcImpl.java:425)
        at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.onCancel(SessionServiceGrpcImpl.java:392)
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.closedInternal(ServerCallImpl.java:378)
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.closed(ServerCallImpl.java:365)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1Closed.runInContext(ServerImpl.java:923)
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
        at io.grpc.internal.SerializeReentrantCallsDirectExecutor.execute(SerializeReentrantCallsDirectExecutor.java:49)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener.closedInternal(ServerImpl.java:930)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener.closed(ServerImpl.java:888)
        at io.grpc.internal.AbstractServerStream$TransportState.closeListener(AbstractServerStream.java:339)
        at io.grpc.internal.AbstractServerStream$TransportState.transportReportStatus(AbstractServerStream.java:283)
        at io.grpc.servlet.jakarta.ServletServerStream$Sink.lambda$cancel$1(ServletServerStream.java:301)
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
        at io.grpc.internal.SerializingExecutor.schedule(SerializingExecutor.java:102)
        at io.grpc.internal.SerializingExecutor.execute(SerializingExecutor.java:95)
        at io.grpc.servlet.jakarta.ServletServerStream$ServletTransportState.runOnTransportThread(ServletServerStream.java:144)
        at io.grpc.servlet.jakarta.ServletServerStream$Sink.cancel(ServletServerStream.java:301)
        at io.grpc.internal.AbstractServerStream.cancel(AbstractServerStream.java:148)
        at io.grpc.servlet.jakarta.ServletAdapter$GrpcReadListener.onError(ServletAdapter.java:346)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:403)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1466)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:596)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:457)
        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.produce(AdaptiveExecutionStrategy.java:194)
        at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:208)
        at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:155)
        at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:378)
        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:969)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
        at java.lang.Thread.run(Thread.java:832)
nbauernfeind commented 1 year ago

I can more easily get these:

io.grpc.StatusRuntimeException: CANCELLED: Stream canceled on the server
        at io.grpc.Status.asRuntimeException(Status.java:539)
        at io.grpc.protobuf.StatusProto.toStatusRuntimeException(StatusProto.java:52)
        at io.deephaven.proto.util.Exceptions.statusRuntimeException(Exceptions.java:14)
        at io.deephaven.server.browserstreaming.BrowserStream$1.onCancel(BrowserStream.java:85)
        at io.deephaven.server.browserstreaming.BrowserStream.close(BrowserStream.java:249)
        at io.deephaven.server.session.SessionState.lambda$onExpired$1(SessionState.java:486)
        at java.util.ArrayList.forEach(ArrayList.java:1511)
        at io.deephaven.server.session.SessionState.onExpired(SessionState.java:484)
        at io.deephaven.server.session.SessionService$SessionCleanupJob.run(SessionService.java:399)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
        at io.deephaven.server.runner.scheduler.SchedulerModule$ThreadFactory.lambda$newThread$0(SchedulerModule.java:78)
        at java.lang.Thread.run(Thread.java:832)

Seems to happen if I open a slowly ticking table, then refresh the page. When the older session times out it prints this log message, but I'm not sure from where!

nbauernfeind commented 1 year ago

Adding -Dhttp.session.durationMs=10000 forces an SRE very quickly on refresh opening this table:

import io.deephaven.engine.util.TableTools
t = TableTools.timeTable("PT1s")