[
https://issues.apache.org/jira/browse/CXF-8926?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17840206#comment-17840206
]
Kai Zander edited comment on CXF-8926 at 4/24/24 7:04 PM:
----------------------------------------------------------
I too am getting the exception [~wilfriedvandenberghe], posted. We're on CXF
4.0.4 and this doesn't necessarily have anything to do with uploading
attachments: Any large request (larger then the chunking threshold) will do,
_if_ the target server rejects a chunk with HTTP 413 and closes the connection.
In our case, we're calling an NGINX with {{client_max_body_size: 1MB}}. When
sending a request that's larger than this limit, _and_ CXF uses chunked
transfer encoding (which it does by default for requests larger than 4096
bytes), NGINX will reject the chunk that exceeds the request body limit and
close the connection.
The {{HttpClient}} used by {{HttpClientHttpConduit}} notices that and cancels
the read subscription, but CXF doesn't notice and it'll hang at
{{PipedOutputStream.write()}}, waiting for read demand that will never come.
The JDK {{HttpClient}} by default uses an {{Executors.newCachedThreadPool()}}
with an idle timeout of 60 seconds. In the best case, where no other requests
are being sent, the thread originally used for "our" request will die after 60
seconds. The {{PipedInputStream}} then finally notices that and we get the
{{"Read end dead"}} exception.
If the application is _not_ idle and the thread pool's threads are _not_
running into their idle timeout, "our" original request may hang indefinitely.
If we enable debug logs for the {{HttpClient}} with
{{-Djdk.httpclient.HttpClient.log=errors,requests,headers,frames:control:data:window,ssl,trace,channel}},
we can see the following:
{code:none}
INFO 2024-04-22 18:25:23,614 HttpClient - MISC: Registering timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,632 HttpClient - CHANNEL: Start reading from
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,632 HttpClient - CHANNEL: Start requesting bytes for
writing to channel: java.nio.channels.SocketChannel[connected
local=/REDACTED:64261 remote=REDACTED/REDACTED:443] - {} -
HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,653 HttpClient - MISC: Canceling timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,653 HttpClient - CHANNEL: HTTP/1 read subscriber got
subscription from https://REDACTED/REDACTED/REDACTED POST - {} -
HttpClient-3-Worker-3
// Start sending data, announcing chunked transfer encoding
INFO 2024-04-22 18:25:23,653 HttpClient - REQUEST:
https://REDACTED/REDACTED/REDACTED POST - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,653 HttpClient - HEADERS: REQUEST HEADERS:
POST /REDACTED HTTP/1.1
Host: REDACTED
Transfer-encoding: chunked
Accept: */*
Content-Type: application/soap+xml; action="REDACTED"; charset=UTF-8
User-Agent: Apache-CXF/4.0.4
- {} - HttpClient-3-Worker-3
// Got response ~200ms later --> Rejected with HTTP 413, connection closed
INFO 2024-04-22 18:25:23,846 HttpClient - HEADERS: RESPONSE HEADERS:
connection: close
content-length: 176
content-type: text/html; charset=utf-8
date: Mon, 22 Apr 2024 16:25:23 GMT
- {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - RESPONSE: (POST
https://REDACTED/REDACTED/REDACTED) 413 HTTP_1_1 Local port: 64261 - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying response filters - {}
- HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying
jdk.internal.net.http.RedirectFilter@40f5ba59 - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying
jdk.internal.net.http.AuthenticationFilter@4e324def - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: All filters applied - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Canceling timer
ResponseTimerEvent[TimeoutEvent[id=5, duration=PT10S,
deadline=2024-04-22T16:25:33.613191800Z]] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Attempting to return
connection to the pool: HttpConnection:
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Closing connection
(keepAlive=false, isOpen=true): HttpConnection:
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Closing: PlainHttpConnection:
HttpConnection: java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Canceling timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
// --> Socket closed
INFO 2024-04-22 18:25:23,846 HttpClient - CHANNEL: Connection close signalled:
connection closed locally (java.nio.channels.SocketChannel[closed]) - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Read error signalled on
channel java.nio.channels.SocketChannel[closed]: java.io.IOException:
connection closed locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Raising error with
subscriber for java.nio.channels.SocketChannel[closed]: java.io.IOException:
connection closed locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - MISC: HttpClient-3-SelectorManager:
java.io.IOException: Channel closed - {} - HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,847 HttpClient - ERROR: HTTP/1 read subscriber
recorded error: <uri unavailable> - java.io.IOException: connection closed
locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Stopped reading from
channel java.nio.channels.SocketChannel[closed] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Failed to write to channel
(java.nio.channels.SocketChannel[closed]:
java.nio.channels.ClosedChannelException) - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Cancelling write
subscription - {} - HttpClient-3-Worker-3
// One minute later, the thread "HttpClient-3-Worker-3" (the reading side/end)
is no longer alive and we get "Read end dead" when attempting to write more data
WARN 2024-04-22 18:26:23,879 PhaseInterceptorChain - Interceptor for REDACTED
has thrown exception, unwinding now - {} - message-consumer-pool-3-thread-2
org.apache.cxf.binding.soap.SoapFault: Problem writing SAAJ model to stream:
Read end dead
{code}
Notice how the {{HttpClient}} immediately notices the server rejecting the
chunk with HTTP 413, but it takes another full minute until the idle timeout
applies, the {{HttpClient}} worker thread dies and CXF notices.
was (Author: JIRAUSER305219):
I too am getting the exception [~wilfriedvandenberghe], posted. We're on CXF
4.0.4 and this doesn't necessarily have anything to do with uploading
attachments: Any large request (larger then the chunking threshold) will do,
_if_ the target server rejects a chunk with HTTP 413 and closes the connection.
In our case, we're calling an NGINX with {{client_max_body_size: 1MB}}. When
sending a request that's larger than this limit, _and_ CXF uses chunked
transfer encoding (which it does by default for requests larger than 4096
bytes), NGINX will reject the chunk that exceeds the request body limit and
close the connection.
The {{HttpClient}} used by {{HttpClientHttpConduit}} notices that and cancels
the read subscription, but CXF doesn't notice and it'll hang at
{{PipedOutputStream.write()}}, waiting for read demand that will never come.
The JDK {{HttpClient}} by default uses an {{Executors.newCachedThreadPool()}}
with an idle timeout of 60 seconds. In the best case, where no other requests
are being sent, the thread originally used for "our" request will die after 60
seconds. The {{PipedInputStream}} then finally notices that and we get the
{{"Read end dead"}} exception.
If the application is _not_ idle and the thread pool's threads are _not_
running into their idle timeout, "our" original request may hang indefinitely.
If we enable debug logs for the {{HttpClient}} with
{{-Djdk.httpclient.HttpClient.log=errors,requests,headers,frames:control:data:window,ssl,trace,channel}},
we can see the following:
{code:plain}
INFO 2024-04-22 18:25:23,614 HttpClient - MISC: Registering timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,632 HttpClient - CHANNEL: Start reading from
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,632 HttpClient - CHANNEL: Start requesting bytes for
writing to channel: java.nio.channels.SocketChannel[connected
local=/REDACTED:64261 remote=REDACTED/REDACTED:443] - {} -
HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,653 HttpClient - MISC: Canceling timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,653 HttpClient - CHANNEL: HTTP/1 read subscriber got
subscription from https://REDACTED/REDACTED/REDACTED POST - {} -
HttpClient-3-Worker-3
// Start sending data, announcing chunked transfer encoding
INFO 2024-04-22 18:25:23,653 HttpClient - REQUEST:
https://REDACTED/REDACTED/REDACTED POST - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,653 HttpClient - HEADERS: REQUEST HEADERS:
POST /REDACTED HTTP/1.1
Host: REDACTED
Transfer-encoding: chunked
Accept: */*
Content-Type: application/soap+xml; action="REDACTED"; charset=UTF-8
User-Agent: Apache-CXF/4.0.4
- {} - HttpClient-3-Worker-3
// Got response ~200ms later --> Rejected with HTTP 413, connection closed
INFO 2024-04-22 18:25:23,846 HttpClient - HEADERS: RESPONSE HEADERS:
connection: close
content-length: 176
content-type: text/html; charset=utf-8
date: Mon, 22 Apr 2024 16:25:23 GMT
- {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - RESPONSE: (POST
https://REDACTED/REDACTED/REDACTED) 413 HTTP_1_1 Local port: 64261 - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying response filters - {}
- HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying
jdk.internal.net.http.RedirectFilter@40f5ba59 - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Applying
jdk.internal.net.http.AuthenticationFilter@4e324def - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: All filters applied - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Canceling timer
ResponseTimerEvent[TimeoutEvent[id=5, duration=PT10S,
deadline=2024-04-22T16:25:33.613191800Z]] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Attempting to return
connection to the pool: HttpConnection:
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Closing connection
(keepAlive=false, isOpen=true): HttpConnection:
java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Closing: PlainHttpConnection:
HttpConnection: java.nio.channels.SocketChannel[connected local=/REDACTED:64261
remote=REDACTED/REDACTED:443] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,846 HttpClient - MISC: Canceling timer
ConnectTimerEvent, TimeoutEvent[id=6, duration=PT5S,
deadline=2024-04-22T16:25:28.614694400Z] - {} - HttpClient-3-Worker-3
// --> Socket closed
INFO 2024-04-22 18:25:23,846 HttpClient - CHANNEL: Connection close signalled:
connection closed locally (java.nio.channels.SocketChannel[closed]) - {} -
HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Read error signalled on
channel java.nio.channels.SocketChannel[closed]: java.io.IOException:
connection closed locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Raising error with
subscriber for java.nio.channels.SocketChannel[closed]: java.io.IOException:
connection closed locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - MISC: HttpClient-3-SelectorManager:
java.io.IOException: Channel closed - {} - HttpClient-3-SelectorManager
INFO 2024-04-22 18:25:23,847 HttpClient - ERROR: HTTP/1 read subscriber
recorded error: <uri unavailable> - java.io.IOException: connection closed
locally - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Stopped reading from
channel java.nio.channels.SocketChannel[closed] - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Failed to write to channel
(java.nio.channels.SocketChannel[closed]:
java.nio.channels.ClosedChannelException) - {} - HttpClient-3-Worker-3
INFO 2024-04-22 18:25:23,847 HttpClient - CHANNEL: Cancelling write
subscription - {} - HttpClient-3-Worker-3
// One minute later, the thread "HttpClient-3-Worker-3" (the reading side/end)
is no longer alive and we get "Read end dead" when attempting to write more data
WARN 2024-04-22 18:26:23,879 PhaseInterceptorChain - Interceptor for REDACTED
has thrown exception, unwinding now - {} - message-consumer-pool-3-thread-2
org.apache.cxf.binding.soap.SoapFault: Problem writing SAAJ model to stream:
Read end dead
{code}
Notice how the {{HttpClient}} immediately notices the server rejecting the
chunk with HTTP 413, but it takes another full minute until the idle timeout
applies, the {{HttpClient}} worker thread dies and CXF notices.
> MTOM - Lock while processing attachment
> ---------------------------------------
>
> Key: CXF-8926
> URL: https://issues.apache.org/jira/browse/CXF-8926
> Project: CXF
> Issue Type: Bug
> Reporter: wilfried
> Priority: Major
>
> I'm currently implementing a SOAP client to send document with CXF 4.0.1 (the
> application is quarkus based).
> My client is working fine when firewall is open between my machine and the
> target server, but in case firewall is closed (for QA environment for
> example), I was expecting to get a timeout, but it's not the case. The SOAP
> client stops its execution to the interceptor *AttachmentOutEndingInterceptor
> *and waits indefinitely.
> After profiling the application, I found out a lock as shown by the below
> thread dump:
> {code:java}
> "executor-thread-2" #296 daemon prio=5 os_prio=0 cpu=31.25ms elapsed=201.04s
> tid=0x0000019f9cd475d0 nid=0x5cf8 in Object.wait() [0x0000009645dfe000]
> java.lang.Thread.State: TIMED_WAITING (on object monitor)
> at java.lang.Object.wait(java.base@17.0.2/Native Method)
> - waiting on <no object reference available>
> at
> java.io.PipedInputStream.awaitSpace(java.base@17.0.2/PipedInputStream.java:273)
> at
> java.io.PipedInputStream.receive(java.base@17.0.2/PipedInputStream.java:231)
> - locked <0x0000000613854b08> (a java.io.PipedInputStream)
> at
> java.io.PipedOutputStream.write(java.base@17.0.2/PipedOutputStream.java:150)
> at
> org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51)
> at
> org.apache.cxf.io.AbstractThresholdOutputStream.write(AbstractThresholdOutputStream.java:69)
> at
> org.apache.cxf.io.CacheAndWriteOutputStream.write(CacheAndWriteOutputStream.java:81)
> at jakarta.activation.DataHandler.writeTo(DataHandler.java:283)
> at
> org.apache.cxf.attachment.AttachmentSerializer.writeAttachments(AttachmentSerializer.java:318)
> at
> org.apache.cxf.interceptor.AttachmentOutInterceptor$AttachmentOutEndingInterceptor.handleMessage(AttachmentOutInterceptor.java:126)
> at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
> - locked <0x0000000613856e30> (a
> org.apache.cxf.phase.PhaseInterceptorChain)
> at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:528)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:439)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:354)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:312)
> at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)
> at
> org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:140)
> at jdk.proxy7.$Proxy235.addMessage(jdk.proxy7/Unknown Source)
> at
> lu.etat.ci.fwt.soap.SOAPTestController.callSaySomethingMtomSecuredCIDUT(SOAPTestController.java:138)
> at
> lu.etat.ci.fwt.soap.SOAPTestController$quarkusrestinvoker$callSaySomethingMtomSecuredCIDUT_1b14f2d5ed1a4d42c824e7582903a9f19063cae3.invoke(Unknown
> Source)
> at
> org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
> at
> io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
> at
> org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
> at
> io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
> at
> org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
> at
> org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1512)
> at
> org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
> at
> org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
> at
> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.lang.Thread.run(java.base@17.0.2/Thread.java:833)
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
