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

chore: Update to Jetty 12 #6037

Draft
wants to merge 16 commits into
base: main
Choose a base branch
from
Draft

Conversation

niloc132
Copy link
Member

@niloc132 niloc132 commented Sep 9, 2024

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 niloc132 added NoDocumentationNeeded jetty dependencies Pull requests that update a dependency file ReleaseNotesNeeded Release notes are needed labels Sep 9, 2024
@niloc132 niloc132 added this to the 0.37.0 milestone Sep 9, 2024
@niloc132 niloc132 requested a review from devinrsmith September 9, 2024 14:17
@niloc132 niloc132 self-assigned this Sep 9, 2024
@niloc132
Copy link
Member Author

niloc132 commented Sep 9, 2024

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 Bump server minimum Java version from 11 to 17 #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.

chipkent
chipkent previously approved these changes Sep 9, 2024
Copy link
Member

@chipkent chipkent left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Files in the py dir LGTM

Copy link
Member

@devinrsmith devinrsmith left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

I see these warnings when starting up the server:

2024-09-10T18:33:22.724Z | qtp909786389-131     |  WARN | o.e.j.e.s.DefaultServlet  | DefaultServlet pathInfoOnly is set to true. Use ResourceServlet instead.                                                                                                                                                                                 
2024-09-10T18:33:22.724Z | qtp909786389-131     |  WARN | o.e.j.e.s.ResourceServlet | Deprecated resourceBase used instead of baseResource                                                                                                                                                                                                     
2024-09-10T18:33:22.726Z | qtp909786389-131     |  WARN | o.e.j.e.s.DefaultServlet  | Incorrect mapping for DefaultServlet at /js-plugins/*. Use ResourceServlet 

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.

Comment on lines +55 to +57
@Override
public Instant lastModified() {
// Always return -1, so that we don't get the build system timestamp. In theory, we could return the app startup
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like Instant.ofEpochMilli(-1) is still treated as a special (as was -1 in Jetty 11), even though it's not documented in the javadoc, at least as used by org.eclipse.jetty.server.ResourceService:

                long ifmsl = HttpDateTime.parseToEpoch(ifms);
                if (ifmsl != -1)
                {
                    long lm = content.getResource().lastModified().toEpochMilli();
                    if (lm != -1 && lm / 1000 <= ifmsl / 1000)
                    {
                        writeHttpError(request, response, callback, HttpStatus.NOT_MODIFIED_304);
                        return true;
                    }
                }

I'm not sure if we actually depend on this behavior, or we just want an old timestamp.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't explicitly depend on this behavior, but we want to ensure that we control the caching through something other than "how old is the file". The last-modified value is stored by the client, and then the server (as you quoted) will send the file contents if the file has changed since that date.

Picking a constant is no good then, since that constant will always be the same, the server will never send a new version. Reading the timestamp from the file on disk is an option (and is the default behavior), but this bites us in another way: a release series might look like

  • 1/1/2024 release 3.1
  • 1/15/2024 release 4.0
  • 2/1/2024 release 3.2

If you update from 3.1 to 3.2 and then to 4.0, the files get older, so we fail this check.

As such, -1 to skip sending the last modified at all is probably the best bet. Other options we considered at the time: record the server start time, or server deployment time (somehow), but -1 still seems safer.

@niloc132
Copy link
Member Author

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.

Copy link
Member

@devinrsmith devinrsmith left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think

-11 projects as build targets in publish-ci.yml

is still outstanding.

@niloc132
Copy link
Member Author

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.

private void safelyComplete() {
try {
// Let the superclass complete the stream so we formally close it
super.complete();
} catch (Exception e) {
// As above, complete() should not throw, so just log this failure and continue.
// This statement is somewhat dubious, since Jetty itself is clearly throwing in
// complete()... leading us to add this try/catch to begin with.
logger.log(Level.FINE, "Error invoking complete() on underlying stream", e);
}
}
@Override
public void complete() {
// Emit trailers as part of the response body, then complete the request. Note that this may mean
// that we don't actually call super.complete() synchronously.
wrappedResponse.writeTrailers(this::safelyComplete);
}

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
Copy link
Member Author

Filed jetty/jetty.project#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 niloc132 marked this pull request as draft September 25, 2024 16:33
@devinrsmith
Copy link
Member

Great bug report; thanks.

@niloc132 niloc132 modified the milestones: 0.37.0, 0.38.0 Nov 8, 2024
@niloc132
Copy link
Member Author

 === 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
dependencies Pull requests that update a dependency file jetty NoDocumentationNeeded ReleaseNotesNeeded Release notes are needed
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Upgrade to Jetty 12
3 participants