Blocked thread if WebApplicationException is reused. #4097

kingsfleet · 2019-04-11T15:24:37Z

I think this exception has been raise a few times; but it never seems to come with a reproducer so the scenario is that after a while there is a number of stuck threads noted in this case by WLS 12.2.1; but I can see that this code would be a problem in the servers:

"[ACTIVE] ExecuteThread: '48' for queue: 'weblogic.kernel.Default (self-tuning)'" #157 daemon prio=5 os_prio=0 tid=0x00007f1c849e2000 nid=0x56c7 waiting on condition [0x00007f1c58318000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007b36845c8> (a jersey.repackaged.com.google.common.util.concurrent.AbstractFuture$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at jersey.repackaged.com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285)
at jersey.repackaged.com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
at org.glassfish.jersey.servlet.internal.ResponseWriter.getResponseContext(ResponseWriter.java:299)
at org.glassfish.jersey.servlet.internal.ResponseWriter.callSendError(ResponseWriter.java:215)
at org.glassfish.jersey.servlet.internal.ResponseWriter.commit(ResponseWriter.java:194)
at org.glassfish.jersey.server.ContainerResponse.close(ContainerResponse.java:413)
at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:784)
at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:444)
at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:490)
at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:334)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:471)
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:425)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:383)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:336)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:223)
at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:286)
at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:260)
at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:137)
at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:350)
at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:25)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at weblogic.security.internal.IDCSSessionSynchronizationFilter.doFilter(IDCSSessionSynchronizationFilter.java:176)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at weblogic.websocket.tyrus.TyrusServletFilter.doFilter(TyrusServletFilter.java:274)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.authorization.CSRFFilter.doFilter(CSRFFilter.java:124)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.service.SlashSlashWarningFilter.doFilter(SlashSlashWarningFilter.java:51)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.authorization.CORSFilter.doFilter(CORSFilter.java:125)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.metrics.DtVisitorTrackingFilter.doFilter(DtVisitorTrackingFilter.java:253)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.authorization.TenantFilter.doFilter(TenantFilter.java:224)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.authorization.TrackingFilter.doFilter(TrackingFilter.java:173)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at com.oracle.breeze.service.inject.LocaleFilter.doFilter(LocaleFilter.java:35)
at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:78)
at oracle.security.jps.ee.http.JpsAbsFilter$3.run(JpsAbsFilter.java:172)

https://github.com/jersey/jersey/issues/3558
https://github.com/jersey/jersey/issues/3800
https://github.com/jersey/jersey/issues/3207
https://github.com/jersey/jersey/issues/3619
#3474

None of these appear to have a reproducible test case, so I have raised this bug in case they are separate concerns.

This behaviour is seen in our code when a WebApplicationException is rethrown by a Guava Cache but the Response in this case is no longer valid as it has previously been used or is in use.

        Response r = Response.status(this.getStatus())
                        .type(getMediaType())
                        // Make it more detectable that someone is trying to re-use this response object
                        // by causing an stream closed IO Exception, do not remove please consult
                        // BUFP-29699 as to why this is a good idea
                        .entity(new StringReader(toJSON()))
                        .build();
        throw new WebApplicationException(response);

Note originally the response was a string; but the problem became more reproducible when we use an entity that cannot be re-used; but it isn't required.

Of course Response is an instance of OutboundJaxrsResponse which holds and instance of OutboundMessageContext which in turns holds a CommittingOutputStream which is not re-usable.

Depending on the load you either see two thread using the CommittingOutputStream at once or errors due to closed streams. It most cases the client in unaware of what has gone wrong and that makes it much harder to track down. Not sure how it gets the right response in this case.

So the deadlock happens in this section of code in SeverRuntime.java:

            try {
                response.setStreamProvider(new OutboundMessageContext.StreamProvider() {
                    @Override
                    public OutputStream getOutputStream(final int contentLength) throws IOException {
                        if (!runtime.disableLocationHeaderRelativeUriResolution) {
                            ServerRuntime.ensureAbsolute(response.getLocation(), response.getHeaders(),
                                    response.getRequestContext(), runtime.rfc7231LocationHeaderRelativeUriResolution);
                        }
                        final OutputStream outputStream = writer.writeResponseStatusAndHeaders(contentLength, response);
                        return isHead ? null : outputStream;
                    }
                });

                if ((writer.enableResponseBuffering() || isHead) && !response.isChunked()) {
                    response.enableBuffering(runtime.configuration);
                }

                try {
                    response.setEntityStream(request.getWorkers().writeTo(
                            entity,
                            entity.getClass(),
                            response.getEntityType(),
                            response.getEntityAnnotations(),
                            response.getMediaType(),
                            response.getHeaders(),
                            request.getPropertiesDelegate(),
                            response.getEntityStream(),
                            request.getWriterInterceptors()));
                } catch (final MappableException mpe) {
                    if (mpe.getCause() instanceof IOException) {
                        connectionCallbackRunner.onDisconnect(processingContext.asyncContext());
                    }
                    throw mpe;
                }
                tracingLogger.log(ServerTraceEvent.FINISHED, response.getStatusInfo());
                tracingLogger.flush(response.getHeaders());

                setWrittenResponse(response);

            } catch (final Throwable ex) {
                if (response.isCommitted()) {
                    /**
                     * We're done with processing here. There's nothing we can do about the exception so
                     * let's just log it.
                     */
                    LOGGER.log(Level.SEVERE, LocalizationMessages.ERROR_WRITING_RESPONSE_ENTITY(), ex);
                } else {
                    skipFinally = true;
                    if (ex instanceof RuntimeException) {
                        throw (RuntimeException) ex;
                    } else {
                        throw new MappableException(ex);
                    }
                }
            } finally {
                if (!skipFinally) {
                    boolean close = !response.isChunked();
                    if (response.isChunked()) {
                        try {
                            response.commitStream();
                        } catch (final Exception e) {
                            LOGGER.log(Level.SEVERE, LocalizationMessages.ERROR_COMMITTING_OUTPUT_STREAM(), e);
                            close = true;
                        }

                        final ChunkedOutput chunked = (ChunkedOutput) entity;
                        try {
                            chunked.setContext(
                                    runtime.requestScope,
                                    runtime.requestScope.referenceCurrent(),
                                    request,
                                    response,
                                    connectionCallbackRunner,
                                    processingContext.asyncContextValue());
                        } catch (final IOException ex) {
                            LOGGER.log(Level.SEVERE, LocalizationMessages.ERROR_WRITING_RESPONSE_ENTITY_CHUNK(), ex);
                            close = true;
                        }
                        // suspend the writer indefinitely (passing null timeout handler is ok in such case) if the output is not
                        // already closed.
                        // TODO what to do if we detect that the writer has already been suspended? override the timeout value?
                        if (!chunked.isClosed()
                                && !writer.suspend(AsyncResponder.NO_TIMEOUT, TimeUnit.SECONDS, null)) {
                            LOGGER.fine(LocalizationMessages.ERROR_SUSPENDING_CHUNKED_OUTPUT_RESPONSE());
                        }
                    }

                    if (close) {
                        try {
                            // the response must be closed here instead of just flushed or committed. Some
                            // output streams writes out bytes only on close (for example GZipOutputStream).
                            response.close();
                        } catch (final Exception e) {
                            LOGGER.log(Level.SEVERE, LocalizationMessages.ERROR_CLOSING_COMMIT_OUTPUT_STREAM(), e);
                        }
                    }
                }
            }

For example if the code in response.enableBuffering(runtime.configuration); fails because someone has already started to use the buffer you end up in the Throwable block before the code in setStreamProvider is executed. This means that when you get to response.close() it eventually get suck in ResponseWriter.commit but the ResponseContext is never set.

So it would make sense if the .get on the future this ResponseWriter had some kind of timeout; but it would be even better if the code properly recovered from this situation. As I say this is a hard was to track down because if the requirement for concurrency and for re-using the same Response object.

I can demonstrate this working in a running system if it helps with a fix, for the moment we worked around this using a trivial subclass:

  /**
     * Provide access to the internal state of the error without having to re-parse the entity body with
     * the problems this entails.
     */
    public static class DetailWebApplicationException extends WebApplicationException {

        @Getter
        private final ExceptionDetailResourceType type;

        /*package*/ DetailWebApplicationException(ExceptionDetailResourceType type) {
            super(type.toResponse());
            this.type = type;
        }

        @Override
        public Response getResponse() {
            // You cannot reuse a response, and in some cases when the exception is cached we find that
            // the exception was being resent to the user causing a thread leakage due to a design flaw
            // in the Jersey runtime, please consult BUFP-29699 before modifying this code.
            return type.toResponse();
        }
    }

But it might be possible to use an interceptor to clone the Response; but I didn't try it.

The text was updated successfully, but these errors were encountered:

alishaarora · 2020-11-12T18:07:48Z

So we ran into the same issue where our threads end up blocked in waiting state and connections in CLOSE_WAIT. This happened with this exception : "An I/O error has occurred while writing a response message entity to the container output stream". For now, we found out the source of these exceptions and fixed it but code should be able to gracefully handle such scenarios and not build up the blocked threads infinitely.

This happens when we see this error:
2020-11-07 00:09:11.702207 GMT Nov 07, 2020 12:09:11 AM org.glassfish.jersey.server.ServerRuntime$Responder writeResponse 2020-11-07 00:09:11.702216 GMT SEVERE: An I/O error has occurred while writing a response message entity to the container output stream. 2020-11-07 00:09:11.702218 GMT java.lang.IllegalStateException: The output stream has already been closed. 2020-11-07 00:09:11.702221 GMT at org.glassfish.jersey.message.internal.CommittingOutputStream.setStreamProvider(CommittingOutputStream.java:118) 2020-11-07 00:09:11.702265 GMT at org.glassfish.jersey.message.internal.OutboundMessageContext.setStreamProvider(OutboundMessageContext.java:805) 2020-11-07 00:09:11.702267 GMT at org.glassfish.jersey.server.ContainerResponse.setStreamProvider(ContainerResponse.java:349) 2020-11-07 00:09:11.702269 GMT at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:621) 2020-11-07 00:09:11.702270 GMT at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:371) 2020-11-07 00:09:11.702283 GMT at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:361) 2020-11-07 00:09:11.702286 GMT at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:256) 2020-11-07 00:09:11.702288 GMT at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) 2020-11-07 00:09:11.702290 GMT at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) 2020-11-07 00:09:11.702312 GMT at org.glassfish.jersey.internal.Errors.process(Errors.java:292) 2020-11-07 00:09:11.702315 GMT at org.glassfish.jersey.internal.Errors.process(Errors.java:274) 2020-11-07 00:09:11.702316 GMT at org.glassfish.jersey.internal.Errors.process(Errors.java:244) 2020-11-07 00:09:11.702318 GMT at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) 2020-11-07 00:09:11.702320 GMT at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) 2020-11-07 00:09:11.702326 GMT at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) 2020-11-07 00:09:11.702328 GMT at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) 2020-11-07 00:09:11.702330 GMT at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) 2020-11-07 00:09:11.702333 GMT at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) 2020-11-07 00:09:11.702339 GMT at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) 2020-11-07 00:09:11.702340 GMT at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) 2020-11-07 00:09:11.702342 GMT at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) 2020-11-07 00:09:11.702344 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) 2020-11-07 00:09:11.702365 GMT at com.yahoo.mextract.jetty.filters.OFilter.doFilter(OFilter.java:55) 2020-11-07 00:09:11.702367 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) 2020-11-07 00:09:11.702369 GMT at com.yahoo.mextract.jetty.filters.CFilter.doFilter(CFilter.java:127) 2020-11-07 00:09:11.702381 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) 2020-11-07 00:09:11.702383 GMT at com.yahoo.mextract.jetty.filters.RFilter.doFilter(RFilter.java:130) 2020-11-07 00:09:11.702384 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) 2020-11-07 00:09:11.702388 GMT at com.yahoo.mextract.jetty.filters.NFilter.doFilter(NFilter.java:111) 2020-11-07 00:09:11.702389 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) 2020-11-07 00:09:11.702390 GMT at com.yahoo.mextract.jetty.filters.MFilter.doFilter(MFilter.java:54) 2020-11-07 00:09:11.702391 GMT at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) 2020-11-07 00:09:11.702395 GMT at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) 2020-11-07 00:09:11.702402 GMT at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) 2020-11-07 00:09:11.702403 GMT at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) 2020-11-07 00:09:11.702405 GMT at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) 2020-11-07 00:09:11.702406 GMT at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) 2020-11-07 00:09:11.702409 GMT at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) 2020-11-07 00:09:11.702411 GMT at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) 2020-11-07 00:09:11.702412 GMT at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) 2020-11-07 00:09:11.702413 GMT at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) 2020-11-07 00:09:11.702416 GMT at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) 2020-11-07 00:09:11.702418 GMT at org.eclipse.jetty.server.Server.handle(Server.java:501) 2020-11-07 00:09:11.702419 GMT at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) 2020-11-07 00:09:11.702420 GMT at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) 2020-11-07 00:09:11.702427 GMT at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) 2020-11-07 00:09:11.702428 GMT at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) 2020-11-07 00:09:11.702429 GMT at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) 2020-11-07 00:09:11.702430 GMT at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) 2020-11-07 00:09:11.702435 GMT at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) 2020-11-07 00:09:11.702436 GMT at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) 2020-11-07 00:09:11.702437 GMT at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) 2020-11-07 00:09:11.702439 GMT at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) 2020-11-07 00:09:11.702442 GMT at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) 2020-11-07 00:09:11.702444 GMT at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) 2020-11-07 00:09:11.702445 GMT at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) 2020-11-07 00:09:11.702446 GMT at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) 2020-11-07 00:09:11.702456 GMT at java.base/java.lang.Thread.run(Thread.java:832)

Thread blocked in waiting state:
"qtp1541019006-122" #122 prio=5 os_prio=0 cpu=3169.04ms elapsed=56.19s tid=0x00007faf8e024800 nid=0xc45 waiting on condition [0x00007faf9519b000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@14/Native Method) - parking to wait for <0x00000007ff806328> (a java.util.concurrent.CompletableFuture$Signaller) at java.util.concurrent.locks.LockSupport.park(java.base@14/LockSupport.java:211) at java.util.concurrent.CompletableFuture$Signaller.block(java.base@14/CompletableFuture.java:1860) at java.util.concurrent.ForkJoinPool.managedBlock(java.base@14/ForkJoinPool.java:3137) at java.util.concurrent.CompletableFuture.waitingGet(java.base@14/CompletableFuture.java:1887) at java.util.concurrent.CompletableFuture.get(java.base@14/CompletableFuture.java:2062) at org.glassfish.jersey.servlet.internal.ResponseWriter.getResponseContext(ResponseWriter.java:275) at org.glassfish.jersey.servlet.internal.ResponseWriter.callSendError(ResponseWriter.java:191) at org.glassfish.jersey.servlet.internal.ResponseWriter.commit(ResponseWriter.java:170) at org.glassfish.jersey.server.ContainerResponse.close(ContainerResponse.java:390) at org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse(ServerRuntime.java:710) at org.glassfish.jersey.server.ServerRuntime$Responder.processResponse(ServerRuntime.java:371) at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:361) at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:256) at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) at org.glassfish.jersey.internal.Errors.process(Errors.java:292) at org.glassfish.jersey.internal.Errors.process(Errors.java:274) at org.glassfish.jersey.internal.Errors.process(Errors.java:244) at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265) at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:232) at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:680) at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:394) at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:346) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:366) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:319) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:205) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:763) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1651) at com.yahoo.mextract.jetty.filters.OFilter.doFilter(OFilter.java:55) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) at com.yahoo.mextract.jetty.filters.CFilter.doFilter(CFilter.java:127) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) at com.yahoo.mextract.jetty.filters.RFilter.doFilter(RFilter.java:130) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) at com.yahoo.mextract.jetty.filters.NFilter.doFilter(NFilter.java:111) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) at com.yahoo.mextract.jetty.filters.MFilter.doFilter(MFilter.java:54) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1638) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:567) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1377) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:507) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1292) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) at org.eclipse.jetty.server.Server.handle(Server.java:501) at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) at org.eclipse.jetty.server.HttpChannel$$Lambda$451/0x000000080130ac40.dispatch(Unknown Source) at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)

jbescos · 2020-12-04T09:38:47Z

How is that WebApplicationExceptionre used by guava cache?. It contains a response, so that exception should never be cached/reused.

alishaarora · 2020-12-04T18:00:35Z

@jbescos Agreed that the response shouldn't be reused. Contrary to the original issue by the reporter, we were not using Guava yet at one point we were reusing the response leading to this scenario. Even then, shouldn't jersey gracefully recover from this situation (or throw exception) rather than having threads wait infinitely?

jbescos · 2020-12-07T08:58:32Z

I think we can set a configurable timeout for the CompletableFuture.get in the line:
org.glassfish.jersey.servlet.internal.ResponseWriter.getResponseContext(ResponseWriter.java:275) at

So it will not be hanged forever.

alishaarora · 2020-12-08T04:18:54Z

@jbescos Yes this should prevent the threads from hanging forever. We had tried it in our server and it prevented the increase in waiting threads thereby alleviating the problem. It will be sufficient although it would be better if in case of an exception in setStreamProvider(), it is handled immediately (in addition to adding timeout).

alishaarora · 2021-01-12T16:58:08Z

@jbescos Which version will this change go in?

jbescos · 2021-01-13T08:52:57Z

@alishaarora sorry for not reply for quite some time. I was discussing this with @jansupol and we decided to not do anything yet.

There are two reasons for this:

The base issue is caused by incorrect user code (reusing the response is not correct), then the fix should be done in user code. This makes this is issue with low priority.
We would like to have a reproducer, so we can know in detail the issue and verify possible solutions.

alishaarora · 2021-01-13T09:17:12Z

@jbescos Thanks for the reply.

Yes the correct fix should be done in user code but can we atleast add a timeout at org.glassfish.jersey.servlet.internal.ResponseWriter.getResponseContext(ResponseWriter.java:275) like you suggested earlier so it prevents the threads from hanging forever? None of the timeouts are honored here and trying to get response context when it can never come back seems odd.
The issue is easily reproducible by reusing the response (there might be other ways to reproduce where output stream is already closed)

jansupol · 2021-01-13T11:30:11Z

The issue is easily reproducible by reusing the response (there might be other ways to reproduce where output stream is already closed

I really wished it would be that simple. If you have that simple reproducer, please add it here. We already spent some time on the reproducer without a success.

migedt · 2022-04-09T16:33:58Z

I created a simple reproducer here: https://github.com/migedt/jersey-issue-4097-reproducer

jbescos · 2022-04-11T06:47:13Z

I get the thread blocked in your example, but I don't get it blocked when I execute the next test:

public class Issue4097Test extends JerseyTest {

    @Override
    protected Application configure() {
        return new ResourceConfig(Issue4097Resource.class);
    }

    @Override
    protected TestContainerFactory getTestContainerFactory() throws TestContainerException {
        return new JettyTestContainerFactory();
    }

    @Test
    public void reuseResponse() throws InterruptedException {
        WebTarget webTarget = target("/issue4097/reuseResponse");
        assertEquals(410, webTarget.request().get().getStatus());
        System.out.println("Received 2nd response (200): " + webTarget.request().get().toString());
        System.out.println("Received 3rd response (hangs): " + webTarget.request().get().toString());
    }

    @Path("/issue4097")
    public static class Issue4097Resource {

        private static final Response RESPONSE =
            Response.status(410).entity("test").build();

        @GET
        @Path("/reuseResponse")
        public Response reuseResponse() {
            // returning the same response is obviously wrong
            return RESPONSE;
        }
    }

}

Anyway, I will review this. Ideally in the second request it should throw one exception.

I am attaching both relevant threads in your example:


main [1] (RUNNABLE)
   sun.nio.ch.SocketDispatcher.read0 line: not available [native method]
   sun.nio.ch.SocketDispatcher.read line: 47 
   sun.nio.ch.NioSocketImpl.tryRead line: 261 
   sun.nio.ch.NioSocketImpl.implRead line: 312 
   sun.nio.ch.NioSocketImpl.read line: 350 
   sun.nio.ch.NioSocketImpl$1.read line: 803 
   java.net.Socket$SocketInputStream.read line: 961 
   java.io.BufferedInputStream.fill line: 244 
   java.io.BufferedInputStream.read1 line: 284 
   java.io.BufferedInputStream.read line: 343 
   sun.net.www.http.HttpClient.parseHTTPHeader line: 788 
   sun.net.www.http.HttpClient.parseHTTP line: 723 
   sun.net.www.protocol.http.HttpURLConnection.getInputStream0 line: 1676 
   sun.net.www.protocol.http.HttpURLConnection.getInputStream line: 1577 
   java.net.HttpURLConnection.getResponseCode line: 527 
   org.glassfish.jersey.client.internal.HttpUrlConnector._apply line: 378 
   org.glassfish.jersey.client.internal.HttpUrlConnector.apply line: 267 
   org.glassfish.jersey.client.ClientRuntime.invoke line: 297 
   org.glassfish.jersey.client.JerseyInvocation.lambda$invoke$0 line: 662 
   org.glassfish.jersey.client.JerseyInvocation$$Lambda$281/0x0000000800d93cb0.call line: not available 
   org.glassfish.jersey.client.JerseyInvocation.call line: 697 
   org.glassfish.jersey.client.JerseyInvocation.lambda$runInScope$3 line: 691 
   org.glassfish.jersey.client.JerseyInvocation$$Lambda$282/0x0000000800d91000.call line: not available 
   org.glassfish.jersey.internal.Errors.process line: 292 
   org.glassfish.jersey.internal.Errors.process line: 274 
   org.glassfish.jersey.internal.Errors.process line: 205 
   org.glassfish.jersey.process.internal.RequestScope.runInScope line: 390 
   org.glassfish.jersey.client.JerseyInvocation.runInScope line: 691 
   org.glassfish.jersey.client.JerseyInvocation.invoke line: 661 
   org.glassfish.jersey.client.JerseyInvocation$Builder.method line: 413 
   org.glassfish.jersey.client.JerseyInvocation$Builder.get line: 313 
   reproducer.Main.main line: 26 

qtp1637070917-21 [21] (WAITING)
   jdk.internal.misc.Unsafe.park line: not available [native method]
   java.util.concurrent.locks.LockSupport.park line: 211 
   java.util.concurrent.CompletableFuture$Signaller.block line: 1864 
   java.util.concurrent.ForkJoinPool.unmanagedBlock line: 3455 
   java.util.concurrent.ForkJoinPool.managedBlock line: 3426 
   java.util.concurrent.CompletableFuture.waitingGet line: 1898 
   java.util.concurrent.CompletableFuture.get line: 2072 
   org.glassfish.jersey.servlet.internal.ResponseWriter.getResponseContext line: 275 
   org.glassfish.jersey.servlet.internal.ResponseWriter.callSendError line: 191 
   org.glassfish.jersey.servlet.internal.ResponseWriter.commit line: 170 
   org.glassfish.jersey.server.ContainerResponse.close line: 390 
   org.glassfish.jersey.server.ServerRuntime$Responder.writeResponse line: 714 
   org.glassfish.jersey.server.ServerRuntime$Responder.processResponse line: 373 
   org.glassfish.jersey.server.ServerRuntime$Responder.process line: 363 
   org.glassfish.jersey.server.ServerRuntime$1.run line: 258 
   org.glassfish.jersey.internal.Errors$1.call line: 248 
   org.glassfish.jersey.internal.Errors$1.call line: 244 
   org.glassfish.jersey.internal.Errors.process line: 292 
   org.glassfish.jersey.internal.Errors.process line: 274 
   org.glassfish.jersey.internal.Errors.process line: 244 
   org.glassfish.jersey.process.internal.RequestScope.runInScope line: 265 
   org.glassfish.jersey.server.ServerRuntime.process line: 234 
   org.glassfish.jersey.server.ApplicationHandler.handle line: 684 
   org.glassfish.jersey.servlet.WebComponent.serviceImpl line: 394 
   org.glassfish.jersey.servlet.WebComponent.service line: 346 
   org.glassfish.jersey.servlet.ServletContainer.service line: 358 
   org.glassfish.jersey.servlet.ServletContainer.service line: 311 
   org.glassfish.jersey.servlet.ServletContainer.service line: 205 
   org.eclipse.jetty.servlet.ServletHolder.handle line: 764 
   org.eclipse.jetty.servlet.ServletHandler.doHandle line: 508 
   org.eclipse.jetty.server.handler.ScopedHandler.nextHandle line: 221 
   org.eclipse.jetty.server.handler.ContextHandler.doHandle line: 1375 
   org.eclipse.jetty.server.handler.ScopedHandler.nextScope line: 176 
   org.eclipse.jetty.servlet.ServletHandler.doScope line: 463 
   org.eclipse.jetty.server.handler.ScopedHandler.nextScope line: 174 
   org.eclipse.jetty.server.handler.ContextHandler.doScope line: 1297 
   org.eclipse.jetty.server.handler.ScopedHandler.handle line: 129 
   org.eclipse.jetty.server.handler.HandlerWrapper.handle line: 122 
   org.eclipse.jetty.server.Server.handle line: 562 
   org.eclipse.jetty.server.HttpChannel.lambda$handle$0 line: 505 
   org.eclipse.jetty.server.HttpChannel$$Lambda$301/0x0000000800db4c20.dispatch line: not available 
   org.eclipse.jetty.server.HttpChannel.dispatch line: 762 
   org.eclipse.jetty.server.HttpChannel.handle line: 497 
   org.eclipse.jetty.server.HttpConnection.onFillable line: 282 
   org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded line: 319 
   org.eclipse.jetty.io.FillInterest.fillable line: 100 
   org.eclipse.jetty.io.SelectableChannelEndPoint$1.run line: 53 
   org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask line: 412 
   org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask line: 381 
   org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce line: 268 
   org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0 line: 138 
   org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy$$Lambda$243/0x0000000800d3f4b8.run line: not available 
   org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run line: 407 
   org.eclipse.jetty.util.thread.QueuedThreadPool.runJob line: 894 
   org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run line: 1038 
   java.lang.Thread.run line: 831

The completable future is completed when the close is invoked, but CommittingOutputStream.close only closes one time. Then the completable future is never completed.

Thread [qtp2017354584-25] (Suspended (breakpoint at line 118 in ResponseWriter))	
	ResponseWriter.writeResponseStatusAndHeaders(long, ContainerResponse) line: 118	
	ServerRuntime$Responder$1.getOutputStream(int) line: 661	
	CommittingOutputStream.commitStream(int) line: 171	
	CommittingOutputStream.flushBuffer(boolean) line: 276	
	CommittingOutputStream.commit() line: 232	
	CommittingOutputStream.close() line: 247	
	OutboundMessageContext.close() line: 842	
	ContainerResponse.close() line: 389	
	ServerRuntime$Responder.writeResponse(ContainerResponse) line: 743	
	ServerRuntime$Responder.processResponse(ContainerResponse) line: 378	
	ServerRuntime$Responder.process(ContainerResponse) line: 368	
	ServerRuntime$1.run() line: 263	
	Errors$1.call() line: 248	
	Errors$1.call() line: 244	
	Errors.process(Callable<T>, boolean) line: 292	
	Errors.process(Producer<T>, boolean) line: 274	
	Errors.process(Runnable) line: 244	
	Hk2RequestScope(RequestScope).runInScope(RequestContext, Runnable) line: 265	
	ServerRuntime.process(ContainerRequest) line: 239	
	ApplicationHandler.handle(ContainerRequest) line: 697	
	WebComponent.serviceImpl(URI, URI, HttpServletRequest, HttpServletResponse) line: 394	
	WebComponent.service(URI, URI, HttpServletRequest, HttpServletResponse) line: 346	
	ServletContainer.service(URI, URI, HttpServletRequest, HttpServletResponse) line: 357	
	ServletContainer.service(HttpServletRequest, HttpServletResponse) line: 311	
	ServletContainer.service(ServletRequest, ServletResponse) line: 205	
	ServletHolder.handle(Request, ServletRequest, ServletResponse) line: 764	
	ServletHandler.doHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 508	
	ServletContextHandler(ScopedHandler).nextHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 221	
	ServletContextHandler(ContextHandler).doHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 1375	
	ServletHandler(ScopedHandler).nextScope(String, Request, HttpServletRequest, HttpServletResponse) line: 176	
	ServletHandler.doScope(String, Request, HttpServletRequest, HttpServletResponse) line: 463	
	ServletContextHandler(ScopedHandler).nextScope(String, Request, HttpServletRequest, HttpServletResponse) line: 174	
	ServletContextHandler(ContextHandler).doScope(String, Request, HttpServletRequest, HttpServletResponse) line: 1297	
	ServletContextHandler(ScopedHandler).handle(String, Request, HttpServletRequest, HttpServletResponse) line: 129	
	Server(HandlerWrapper).handle(String, Request, HttpServletRequest, HttpServletResponse) line: 122	
	Server.handle(HttpChannel) line: 562	
	HttpChannelOverHttp(HttpChannel).lambda$handle$0() line: 505	
	0x0000000800e136e8.dispatch() line: not available	
	HttpChannelOverHttp(HttpChannel).dispatch(DispatcherType, HttpChannel$Dispatchable) line: 762	
	HttpChannelOverHttp(HttpChannel).handle() line: 497	
	HttpConnection.onFillable() line: 282	
	AbstractConnection$ReadCallback.succeeded() line: 319	
	AbstractEndPoint$1(FillInterest).fillable() line: 100	
	SelectableChannelEndPoint$1.run() line: 53	
	QueuedThreadPool.runJob(Runnable) line: 894	
	QueuedThreadPool$Runner.run() line: 1038	
	Thread.run() line: 831

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>

* Blocked thread if WebApplicationException is reused. #4097 Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>

jbescos added a commit to jbescos/jersey that referenced this issue Apr 11, 2022

Blocked thread if WebApplicationException is reused. eclipse-ee4j#4097

035b24a

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>

jbescos added a commit to jbescos/jersey that referenced this issue Apr 11, 2022

Blocked thread if WebApplicationException is reused. eclipse-ee4j#4097

fb651e2

Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>

jbescos mentioned this issue Apr 11, 2022

Blocked thread if WebApplicationException is reused. #4097 #5035

Merged

jansupol pushed a commit that referenced this issue Apr 29, 2022

Blocked thread if WebApplicationException is reused. #4097 (#5035)

5b352d8

* Blocked thread if WebApplicationException is reused. #4097 Signed-off-by: Jorge Bescos Gascon <jorge.bescos.gascon@oracle.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Blocked thread if WebApplicationException is reused. #4097

Blocked thread if WebApplicationException is reused. #4097

kingsfleet commented Apr 11, 2019 •

edited

alishaarora commented Nov 12, 2020

jbescos commented Dec 4, 2020 •

edited

alishaarora commented Dec 4, 2020

jbescos commented Dec 7, 2020

alishaarora commented Dec 8, 2020 •

edited

alishaarora commented Jan 12, 2021

jbescos commented Jan 13, 2021

alishaarora commented Jan 13, 2021

jansupol commented Jan 13, 2021

migedt commented Apr 9, 2022

jbescos commented Apr 11, 2022 •

edited

Blocked thread if WebApplicationException is reused. #4097

Blocked thread if WebApplicationException is reused. #4097

Comments

kingsfleet commented Apr 11, 2019 • edited

alishaarora commented Nov 12, 2020

jbescos commented Dec 4, 2020 • edited

alishaarora commented Dec 4, 2020

jbescos commented Dec 7, 2020

alishaarora commented Dec 8, 2020 • edited

alishaarora commented Jan 12, 2021

jbescos commented Jan 13, 2021

alishaarora commented Jan 13, 2021

jansupol commented Jan 13, 2021

migedt commented Apr 9, 2022

jbescos commented Apr 11, 2022 • edited

kingsfleet commented Apr 11, 2019 •

edited

jbescos commented Dec 4, 2020 •

edited

alishaarora commented Dec 8, 2020 •

edited

jbescos commented Apr 11, 2022 •

edited