deephaven-core icon indicating copy to clipboard operation
deephaven-core copied to clipboard

chore: Update to Jetty 12

Open niloc132 opened this issue 1 year ago • 5 comments

Jetty 10/11 are expected to reach End of Life next year, this updates our default server implementation to Jetty 12, and in turn requires Java 17+ at runtime.

Keeps the old Jetty 11 artifact in a new module, release notes will clarify how to keep Jetty 11 (and Java 11) support.

Fixes #5264

niloc132 avatar Sep 09 '24 14:09 niloc132

Notes for reviewers:

  • We might want to pull out a server-servlet project with the shared servlets between jetty 11 and 12, to avoid quite as much duplication as we have here.
  • When we remove the Jetty 11 impl, we should also close https://github.com/deephaven/deephaven-core/issues/4703 and bump to java 17 for everything that isn't flight-client (... assuming we never update the actual arrow API and require newer Java there too)
  • Important to note that this will require Java 17 when installed as a python library, should be mentioned in release notes.
  • We might want to rename a few classes to avoid resolving confusion only by class name.

niloc132 avatar Sep 09 '24 14:09 niloc132

Looks mostly straightforward; I did not review any of the "new" -11 projects, I'm assuming they are simple moves of the existing projects.

Correct - the commits in this branch are separated to allow for easier review, the first is "move everything to jetty 11 projects and packages", the second adds a jetty 12 impl (as "server-jetty" etc), and so on.

I see these warnings when starting up the server:

Good catch, I'll see if I can resolve this quickly.

I think we'll want to explicitly add the -11 projects as build targets in publish-ci.yml; I'm not sure whether we'll actually want to publish a native application tar for 11? I think DHE only consumes the JARs from maven central, so does not care about a native application artifact.

Do we get download stats on those GH artifacts? If so, maybe we leave them for a release or two then phase them out, potentially sooner than we might phase out the DHE dependency on the jars from maven central.

niloc132 avatar Sep 10 '24 20:09 niloc132

Devin discovered that Jetty 12 is noisier when connections are stopped abruptly. We have two use cases that give us three (and a half) stack traces to investigate:

Connecting using a web browser to an SSL enabled server, then closing the page produces a pair of exceptions (multiple times, only considering the first pair here, as one error might cause others):

2024-09-20T14:42:31.295Z | heduler-Concurrent-2 |  WARN | g.s.j.ServletServerStream | [{ServletAdapter<11>}] Exception writing message
org.eclipse.jetty.io.EofException: Closed
	at org.eclipse.jetty.ee10.servlet.HttpOutput.checkWritable(HttpOutput.java:701)
	at org.eclipse.jetty.ee10.servlet.HttpOutput.write(HttpOutput.java:731)
	at io.grpc.servlet.jakarta.web.GrpcWebOutputStream.write(GrpcWebOutputStream.java:90)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.lambda$writeBytes$4(AsyncServletOutputStreamWriter.java:108)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.runOrBuffer(AsyncServletOutputStreamWriter.java:183)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.writeBytes(AsyncServletOutputStreamWriter.java:105)
	at io.grpc.servlet.jakarta.ServletServerStream$Sink.writeFrame(ServletServerStream.java:261)
	at io.grpc.internal.AbstractServerStream.deliverFrame(AbstractServerStream.java:118)
	at io.grpc.internal.MessageFramer.commitToSink(MessageFramer.java:354)
	at io.grpc.internal.MessageFramer.flush(MessageFramer.java:304)
	at io.grpc.internal.AbstractStream.flush(AbstractStream.java:76)
	at io.grpc.internal.ServerCallImpl.sendMessageInternal(ServerCallImpl.java:170)
	at io.grpc.internal.ServerCallImpl.sendMessage(ServerCallImpl.java:152)
	at io.grpc.ForwardingServerCall.sendMessage(ForwardingServerCall.java:32)
	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onNext(ServerCalls.java:380)
	at io.deephaven.extensions.barrage.util.GrpcUtil.lambda$safelyOnNext$0(GrpcUtil.java:48)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyExecuteLocked(GrpcUtil.java:33)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyOnNext(GrpcUtil.java:48)
	at io.deephaven.server.console.ConsoleServiceGrpcImpl$LogsClient.run(ConsoleServiceGrpcImpl.java:475)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at io.deephaven.server.runner.scheduler.SchedulerModule$ThreadFactory.lambda$newThread$0(SchedulerModule.java:100)
	at java.base/java.lang.Thread.run(Thread.java:840)
2024-09-20T14:42:31.297Z | heduler-Concurrent-2 |  WARN | i.g.i.ServerCallImpl      | Cancelling the stream because of internal error
java.lang.IllegalStateException: Request/Response does not exist (likely recycled)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.getServletContextResponse(ServletChannel.java:283)
	at org.eclipse.jetty.ee10.servlet.ServletChannelState.isResponseCommitted(ServletChannelState.java:360)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.isCommitted(ServletChannel.java:772)
	at org.eclipse.jetty.ee10.servlet.ServletApiResponse.isCommitted(ServletApiResponse.java:423)
	at jakarta.servlet.ServletResponseWrapper.isCommitted(ServletResponseWrapper.java:175)
	at io.grpc.servlet.jakarta.ServletServerStream$Sink.cancel(ServletServerStream.java:298)
	at io.grpc.servlet.jakarta.ServletServerStream$Sink.writeFrame(ServletServerStream.java:269)
	at io.grpc.internal.AbstractServerStream.deliverFrame(AbstractServerStream.java:118)
	at io.grpc.internal.MessageFramer.commitToSink(MessageFramer.java:354)
	at io.grpc.internal.MessageFramer.flush(MessageFramer.java:304)
	at io.grpc.internal.AbstractStream.flush(AbstractStream.java:76)
	at io.grpc.internal.ServerCallImpl.sendMessageInternal(ServerCallImpl.java:170)
	at io.grpc.internal.ServerCallImpl.sendMessage(ServerCallImpl.java:152)
	at io.grpc.ForwardingServerCall.sendMessage(ForwardingServerCall.java:32)
	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onNext(ServerCalls.java:380)
	at io.deephaven.extensions.barrage.util.GrpcUtil.lambda$safelyOnNext$0(GrpcUtil.java:48)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyExecuteLocked(GrpcUtil.java:33)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyOnNext(GrpcUtil.java:48)
	at io.deephaven.server.console.ConsoleServiceGrpcImpl$LogsClient.run(ConsoleServiceGrpcImpl.java:475)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at io.deephaven.server.runner.scheduler.SchedulerModule$ThreadFactory.lambda$newThread$0(SchedulerModule.java:100)
	at java.base/java.lang.Thread.run(Thread.java:840)

The first exception comes from ExportedTableUpdateListener.onCompleted trying to log a "ExportedTableUpdateListener(5fd9c9e7) is complete" message while the log stream is shutting down. The TableService/ExportedTableUpdates stream is canceled from the client, and is handled by the grpc servlet implementation of jakarta.servlet.AsyncListener.onError. That is propagated to the onCompleted mentioned above, which tries to log a message, which then tries to be written to the ConsoleService/SubscribeToLogs stream. However, that stream apparently wasn't notified - ConsoleServiceGrpcImpl.LogsClient.onCancel() is never invoked.

The second in this pair may plausibly be an error in the gRPC servlet implementation, which continues to attempt to write in some error cases, even after it knows that the write has failed. With that said, the contract for jakarta.servlet.ServletResponse.isCommitted is

    /**
     * Returns a boolean indicating if the response has been committed. A committed response has already had its status code
     * and headers written.
     *
     * @return a boolean indicating if the response has been committed
     *
     * @see #setBufferSize
     * @see #getBufferSize
     * @see #flushBuffer
     * @see #reset
     *
     */
    public boolean isCommitted();

which doesn't seem to allow for throwing instead of returning "true". In fact, the Jetty implementation specifically returns true in some error states, from org.eclipse.jetty.server.Response:

        // If we are in sendError state, we pretend to be committed
        if (_channel.isSendError())
            return true;

which seems like it could be reasonable to expect in other error states as well?


This third case can be repro'd with either http or https: ./java-client/session-examples/build/install/java-client-session-examples/bin/subscribe-fields --ssl server/dev-certs/client.json --target dh://localhost:8443 or ./java-client/session-examples/build/install/java-client-session-examples/bin/subscribe-fields --ssl server/dev-certs/client.json --target dh+plain://localhost:10000

java.lang.IllegalStateException: s=IDLE rs=BLOCKING os=ABORTED is=IDLE awp=false se=false i=true al=0
	at org.eclipse.jetty.ee10.servlet.ServletChannelState.complete(ServletChannelState.java:817)
	at org.eclipse.jetty.ee10.servlet.AsyncContextState.complete(AsyncContextState.java:61)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.lambda$new$1(AsyncServletOutputStreamWriter.java:97)
	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.AsyncServletOutputStreamWriter.lambda$new$2(AsyncServletOutputStreamWriter.java:94)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.runOrBuffer(AsyncServletOutputStreamWriter.java:183)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.complete(AsyncServletOutputStreamWriter.java:127)
	at io.grpc.servlet.jakarta.ServletServerStream$Sink.writeTrailers(ServletServerStream.java:293)
	at io.grpc.internal.AbstractServerStream.close(AbstractServerStream.java:133)
	at io.grpc.internal.ServerCallImpl.closeInternal(ServerCallImpl.java:222)
	at io.grpc.internal.ServerCallImpl.close(ServerCallImpl.java:208)
	at io.grpc.PartialForwardingServerCall.close(PartialForwardingServerCall.java:48)
	at io.grpc.ForwardingServerCall.close(ForwardingServerCall.java:22)
	at io.grpc.ForwardingServerCall$SimpleForwardingServerCall.close(ForwardingServerCall.java:44)
	at io.deephaven.server.session.SessionServiceGrpcImpl$InterceptedCall.close(SessionServiceGrpcImpl.java:295)
	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onError(ServerCalls.java:389)
	at io.deephaven.extensions.barrage.util.GrpcUtil.lambda$safelyError$2(GrpcUtil.java:97)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyExecuteLocked(GrpcUtil.java:33)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyError(GrpcUtil.java:97)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyError(GrpcUtil.java:85)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl$Subscription.notifyObserverCancelled(ApplicationServiceGrpcImpl.java:254)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl.remove(ApplicationServiceGrpcImpl.java:148)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl$Subscription.close(ApplicationServiceGrpcImpl.java:233)
	at io.deephaven.server.session.SessionState.lambda$onExpired$1(SessionState.java:496)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at io.deephaven.server.session.SessionState.onExpired(SessionState.java:494)
	at io.deephaven.server.session.SessionService.closeSession(SessionService.java:408)
	at io.deephaven.server.session.SessionServiceGrpcImpl.closeSession(SessionServiceGrpcImpl.java:126)
	at io.deephaven.proto.backplane.grpc.SessionServiceGrpc$MethodHandlers.invoke(SessionServiceGrpc.java:871)
	at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.lambda$onHalfClose$1(SessionServiceGrpcImpl.java:437)
	at io.deephaven.server.session.SessionServiceGrpcImpl.rpcWrapper(SessionServiceGrpcImpl.java:481)
	at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.onHalfClose(SessionServiceGrpcImpl.java:437)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:351)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:860)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializeReentrantCallsDirectExecutor.execute(SerializeReentrantCallsDirectExecutor.java:49)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener.halfClosed(ServerImpl.java:868)
	at io.grpc.internal.AbstractServerStream$TransportState.deframerClosed(AbstractServerStream.java:238)
	at io.grpc.internal.MessageDeframer.close(MessageDeframer.java:234)
	at io.grpc.internal.MessageDeframer.closeWhenComplete(MessageDeframer.java:192)
	at io.grpc.internal.AbstractStream$TransportState.closeDeframer(AbstractStream.java:201)
	at io.grpc.internal.AbstractServerStream$TransportState.inboundDataReceived(AbstractServerStream.java:265)
	at io.grpc.servlet.jakarta.ServletAdapter$GrpcReadListener.lambda$onAllDataRead$1(ServletAdapter.java:337)
	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.ServletAdapter$GrpcReadListener.onAllDataRead(ServletAdapter.java:336)
	at org.eclipse.jetty.ee10.servlet.HttpInput.run(HttpInput.java:365)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$1(ServletChannel.java:542)
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1507)
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1500)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:542)
	at org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:464)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:575)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
	at org.eclipse.jetty.server.Handler$Wrapper.handle(Handler.java:740)
	at org.eclipse.jetty.server.handler.CrossOriginHandler.handle(CrossOriginHandler.java:336)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:549)
	at org.eclipse.jetty.server.Server.handle(Server.java:181)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:661)
	at org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:105)
	at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
	at org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:574)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	at java.base/java.lang.Thread.run(Thread.java:840)

or

java.lang.IllegalStateException: s=IDLE rs=BLOCKING os=ABORTED is=IDLE awp=false se=false i=true al=0
	at org.eclipse.jetty.ee10.servlet.ServletChannelState.complete(ServletChannelState.java:817)
	at org.eclipse.jetty.ee10.servlet.AsyncContextState.complete(AsyncContextState.java:61)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.lambda$new$1(AsyncServletOutputStreamWriter.java:97)
	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.AsyncServletOutputStreamWriter.lambda$new$2(AsyncServletOutputStreamWriter.java:94)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.runOrBuffer(AsyncServletOutputStreamWriter.java:183)
	at io.grpc.servlet.jakarta.AsyncServletOutputStreamWriter.complete(AsyncServletOutputStreamWriter.java:127)
	at io.grpc.servlet.jakarta.ServletServerStream$Sink.writeTrailers(ServletServerStream.java:293)
	at io.grpc.internal.AbstractServerStream.close(AbstractServerStream.java:133)
	at io.grpc.internal.ServerCallImpl.closeInternal(ServerCallImpl.java:222)
	at io.grpc.internal.ServerCallImpl.close(ServerCallImpl.java:208)
	at io.grpc.PartialForwardingServerCall.close(PartialForwardingServerCall.java:48)
	at io.grpc.ForwardingServerCall.close(ForwardingServerCall.java:22)
	at io.grpc.ForwardingServerCall$SimpleForwardingServerCall.close(ForwardingServerCall.java:44)
	at io.deephaven.server.session.SessionServiceGrpcImpl$InterceptedCall.close(SessionServiceGrpcImpl.java:295)
	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onError(ServerCalls.java:389)
	at io.deephaven.extensions.barrage.util.GrpcUtil.lambda$safelyError$2(GrpcUtil.java:97)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyExecuteLocked(GrpcUtil.java:33)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyError(GrpcUtil.java:97)
	at io.deephaven.extensions.barrage.util.GrpcUtil.safelyError(GrpcUtil.java:85)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl$Subscription.notifyObserverCancelled(ApplicationServiceGrpcImpl.java:254)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl.remove(ApplicationServiceGrpcImpl.java:148)
	at io.deephaven.server.appmode.ApplicationServiceGrpcImpl$Subscription.close(ApplicationServiceGrpcImpl.java:233)
	at io.deephaven.server.session.SessionState.lambda$onExpired$1(SessionState.java:496)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at io.deephaven.server.session.SessionState.onExpired(SessionState.java:494)
	at io.deephaven.server.session.SessionService.closeSession(SessionService.java:408)
	at io.deephaven.server.session.SessionServiceGrpcImpl.closeSession(SessionServiceGrpcImpl.java:126)
	at io.deephaven.proto.backplane.grpc.SessionServiceGrpc$MethodHandlers.invoke(SessionServiceGrpc.java:871)
	at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.lambda$onHalfClose$1(SessionServiceGrpcImpl.java:437)
	at io.deephaven.server.session.SessionServiceGrpcImpl.rpcWrapper(SessionServiceGrpcImpl.java:481)
	at io.deephaven.server.session.SessionServiceGrpcImpl$SessionServiceCallListener.onHalfClose(SessionServiceGrpcImpl.java:437)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:351)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:860)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializeReentrantCallsDirectExecutor.execute(SerializeReentrantCallsDirectExecutor.java:49)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener.halfClosed(ServerImpl.java:868)
	at io.grpc.internal.AbstractServerStream$TransportState.deframerClosed(AbstractServerStream.java:238)
	at io.grpc.internal.MessageDeframer.close(MessageDeframer.java:234)
	at io.grpc.internal.MessageDeframer.closeWhenComplete(MessageDeframer.java:192)
	at io.grpc.internal.AbstractStream$TransportState.closeDeframer(AbstractStream.java:201)
	at io.grpc.internal.AbstractServerStream$TransportState.inboundDataReceived(AbstractServerStream.java:265)
	at io.grpc.servlet.jakarta.ServletAdapter$GrpcReadListener.lambda$onAllDataRead$1(ServletAdapter.java:337)
	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.ServletAdapter$GrpcReadListener.onAllDataRead(ServletAdapter.java:336)
	at org.eclipse.jetty.ee10.servlet.HttpInput.run(HttpInput.java:365)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.lambda$handle$1(ServletChannel.java:542)
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1507)
	at org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1500)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:542)
	at org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:464)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:575)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
	at org.eclipse.jetty.server.Handler$Wrapper.handle(Handler.java:740)
	at org.eclipse.jetty.server.handler.CrossOriginHandler.handle(CrossOriginHandler.java:336)
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:549)
	at org.eclipse.jetty.server.Server.handle(Server.java:181)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:661)
	at org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:105)
	at org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
	at java.base/java.lang.Thread.run(Thread.java:840)

I'm treating these as only one and a half stack traces, but this does serve to point out that the issue we're experiencing isn't specific to ssl.

The client here makes a call to SessionService/CloseSession - when the server handles that, it expires the entire session which synchronously closes the other active gRPC calls with a CANCELED status - for example, the ApplicationService/ListFields call gets a "subscription cancelled" message.

However, the ListFields call was already aborted from the jetty side, but we don't seem to get a notification. Tracing the same path in Jetty 12, the GrpcReadListener.onError method was called as the client canceled the call on shutdown, so this may be a regression in Jetty 12. I'll break this out into its own example project and file with Jetty.

Note that we somewhat anticipated this issue in our GrpcWebFilter implementation, which in GrpcWebServletRequest catches exceptions from complete() and logs them rather than rethrowing them. https://github.com/deephaven/deephaven-core/blob/ff5478dcb3ec1d1eb2d6fc43db0d7aa27da4a01c/grpc-java/grpc-servlet-jakarta/src/main/java/io/grpc/servlet/jakarta/web/GrpcWebServletRequest.java#L62-L80

I think the root cause on both cases is the same - Jetty doesn't seem to be notifying the client of failures on all streams - perhaps only one stream per transport gets the notification? I'll try to reproduce and file this so we can continue.

niloc132 avatar Sep 20 '24 16:09 niloc132

Filed https://github.com/jetty/jetty.project/issues/12313 to track this with Jetty - at this time I believe all three stack traces result from this.

I also believe that we likely could ignore this issue without negative impacts from the client's perspective, but leaving streams open longer than necessary (until the server next tries to write) will consume unnecessary resources, so we should hold off on updating to Jetty 12 until we have this resolved.

niloc132 avatar Sep 25 '24 16:09 niloc132

Great bug report; thanks.

devinrsmith avatar Sep 25 '24 17:09 devinrsmith

 === RUN   TestOpenTable
    test_tools.go:67: OpenTable error rpc error: code = Unavailable desc = error reading from server: EOF
--- FAIL: TestOpenTable (0.02s)

Need to nail down what is causing that and see about a fix both for jetty 11 (approx vers 11.0.24) and 12.

niloc132 avatar Nov 12 '24 17:11 niloc132

Coverage runs fail with this patch - when performing the merge locally with --stacktrace, I get this:

java.lang.IllegalStateException: Can't add different class with same name: io/deephaven/server/flightsql/FlightSqlResolver_Factory
        at org.jacoco.core.analysis.CoverageBuilder.visitCoverage(CoverageBuilder.java:106)
        at org.jacoco.core.analysis.Analyzer$1.visitEnd(Analyzer.java:100)
        at org.objectweb.asm.ClassVisitor.visitEnd(ClassVisitor.java:395)
        at org.jacoco.core.internal.flow.ClassProbesAdapter.visitEnd(ClassProbesAdapter.java:100)
        at org.objectweb.asm.ClassReader.accept(ClassReader.java:749)
        at org.objectweb.asm.ClassReader.accept(ClassReader.java:425)
        at org.jacoco.core.analysis.Analyzer.analyzeClass(Analyzer.java:117)
        at org.jacoco.core.analysis.Analyzer.analyzeClass(Analyzer.java:133)
        ... 159 more

This is because both server-jetty-app and server-jetty-app-11 generate the same code via dagger for flightsql: io.deephaven.server.flightsql.FlightSqlResolver_Factory. This appears to be the only such class duplicated, at a quick glance - perhaps we can just disable jacoco for jetty 11?

@devinrsmith (and @stanbrub)

niloc132 avatar Mar 28 '25 19:03 niloc132

I've added a fix that excludes server-jetty-*-11 from jacoco's reporting, this seems to resolve the issue locally.

niloc132 avatar Mar 28 '25 20:03 niloc132

@devinrsmith @cpwright I re-enabled the Java 11 testSerial/Parallel/OutOfBand tests, CI is just about finished for nightly and coverage builds: https://github.com/niloc132/deephaven-core/actions/runs/14228203468 https://github.com/niloc132/deephaven-core/actions/runs/14228200421

niloc132 avatar Apr 02 '25 21:04 niloc132