Am 2019-07-02 um 17:18 schrieb Christopher Schultz:
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Michael,
On 7/2/19 10:40, Osipov, Michael wrote:
Hi folks,
I am trying to understand a sporadic failure (several times a day)
where a request proxied by HTTPd takes so long that the default
timeout of mod_proxy drops the request with 503.
The Tomcat:
VersionLoggerListener.log Server version: Apache
Tomcat/8.5.38 VersionLoggerListener.log Server built:
Feb 5 2019 11:42:42 UTC VersionLoggerListener.log Server number:
8.5.38.0 VersionLoggerListener.log OS Name:
FreeBSD VersionLoggerListener.log OS Version:
12.0-STABLE VersionLoggerListener.log Architecture:
amd64 VersionLoggerListener.log Java Home:
/usr/local/openjdk8/jre VersionLoggerListener.log JVM Version:
1.8.0_202-b08 VersionLoggerListener.log JVM Vendor:
Oracle Corporation VersionLoggerListener.log CATALINA_BASE:
/usr/local/ldadocgen/prod/tomcat-1 VersionLoggerListener.log
CATALINA_HOME: /usr/local/apache-tomcat-8.5
VersionLoggerListener.log Command line argument:
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
VersionLoggerListener.log Command line argument:
-Djava.util.logging.config.file=/usr/local/ldadocgen/prod/tomcat-1/co
nf/logging.properties
VersionLoggerListener.log Command line argument:
-Djava.security.auth.login.config=/usr/local/apache-tomcat-8.5/conf/l
ogin.conf
VersionLoggerListener.log Command line argument:
-Djavax.security.auth.useSubjectCredsOnly=false
VersionLoggerListener.log Command line argument:
-Xbootclasspath/p:/usr/local/apache-tomcat-8.5/bin/activedirectory-ld
ap-hack-0.2.1.jar
VersionLoggerListener.log Command line argument:
-Dcom.sun.management.jmxremote VersionLoggerListener.log Command
line argument: -Djava.awt.headless=true VersionLoggerListener.log
Command line argument:
-Djava.endorsed.dirs=/usr/local/apache-tomcat-8.5/endorsed
VersionLoggerListener.log Command line argument:
-Dcatalina.home=/usr/local/apache-tomcat-8.5
VersionLoggerListener.log Command line argument:
-Dcatalina.base=/usr/local/ldadocgen/prod/tomcat-1
VersionLoggerListener.log Command line argument:
-Djava.io.tmpdir=/usr/local/ldadocgen/prod/tomcat-1/temp
VersionLoggerListener.log Command line argument:
-Dcommons.daemon.process.id=1287 VersionLoggerListener.log
Command line argument: -Dcommons.daemon.process.parent=1286
VersionLoggerListener.log Command line argument:
-Dcommons.daemon.version=1.1.0 VersionLoggerListener.log Command
line argument: abort AprLifecycleListener.lifecycleEvent Loaded
APR based Apache Tomcat Native library [1.2.21] using APR version
[1.6.5]. AprLifecycleListener.lifecycleEvent APR capabilities:
IPv6 [true], sendfile [true], accept filters [true], random
[true]. AprLifecycleListener.lifecycleEvent APR/OpenSSL
configuration: useAprConnector [true], useOpenSSL [true]
AprLifecycleListener.initializeSSL OpenSSL successfully
initialized [OpenSSL 1.1.1a-freebsd 20 Nov 2018]
AbstractProtocol.init Initializing ProtocolHandler
["http-apr-127.0.1.2-8081"] AbstractProtocol.init Initializing
ProtocolHandler ["https-openssl-apr-147.54.64.149-8444"]
Catalina.load Initialization processed in 1107 ms
Apache HTTPd 2.4.39 (worker MPM) from FreeBSD ports with following
patch [1] applied because we are waiting for 2.4.40 where BZ 60330
is fixed (hopefully).
Note that directly going against :8444 is lightnight fast and the
POST operation takes about a second in average, but via HTTPd it
may take up to a minute.
server.xml:
<Connector address="localhost" port="8081"
connectionTimeout="20000" maxHttpHeaderSize="24576"
redirectPort="8444" maxThreads="250" />
httpd.conf:
<Location "/prod"> ProxyPreserveHost On ProxyPass
http://localhost:8081/prod ProxyPassReverse
http://localhost:8081/prod </Location>
Note: I cannot use mod_proxy_ajp because "Expect: 100-continue" is
not supported.
HTTPd access log:
147.54.64.28 - 2019-07-02T13:59:52.921 "POST /prod/api/documents
HTTP/1.1" 503 425 60014
HTTPd error log:
[Tue Jul 02 13:59:52.898403 2019] [ssl:info] [pid 1389:tid
34389566208] [client 147.54.64.28:50106] AH01964: Connection to
child 7 established (server sitex-ldadw.ad001.siemens.net:443)
[Tue Jul 02 14:00:52.935644 2019] [proxy_http:error] [pid
1389:tid 34389566208] (70007)The timeout specified has expired:
[client 147.54.64.28:50106] AH01102: error reading status line
from remote server localhost:8081 [Tue Jul 02 14:00:52.935692
2019] [proxy:error] [pid 1389:tid 34389566208] [client
147.54.64.28:50106] AH00898: Timeout on 100-Continue returned by
/prod/api/documents [Tue Jul 02 14:01:45.738821 2019] [ssl:info]
[pid 1389:tid 34389566208] [client 147.54.64.28:50244] AH01964:
Connection to child 7 established (server
sitex-ldadw.ad001.siemens.net:443) [Tue Jul 02 14:02:02.589847
2019] [ssl:info] [pid 1389:tid 34389566208] [client
147.54.64.28:50261] AH01964: Connection to child 7 established
(server sitex-ldadw.ad001.siemens.net:443)
The third line somes from ./modules/proxy/mod_proxy_http.c:
L1241/1251
Tomcat access log:
147.54.64.28 uawet...@ad001.siemens.net 2019-07-02T14:02:12.215
"POST /prod/api/documents HTTP/1.1" 500 - 139293
As well as the application log:
2019-07-02 14:02:12,212 [http-apr-127.0.1.2-8081-exec-3] INFO
c.s.d.l.w.c.DocumentsController - Saving request body from user
'uawet...@ad001.siemens.net' to
'/usr/local/ldadocgen/prod/tomcat-1/temp/lda-docgen.88533484902573671
25.zip'
2019-07-02 14:02:12,213 [http-apr-127.0.1.2-8081-exec-3] ERROR
c.s.d.l.w.c.DocumentsController - Saving request body to
'/usr/local/ldadocgen/prod/tomcat-1/temp/lda-docgen.88533484902573671
25.zip'
failed
org.apache.catalina.connector.ClientAbortException:
java.io.IOException: Unexpected error [54] reading data from the
APR/native socket [45,112,807,584] with wrapper
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@70c3965:4511
2807584].
at
org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.j
ava:348)
at
org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuf
fer.java:663)
at
org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:370)
at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStrea
m.java:152)
at java.nio.file.Files.copy(Files.java:2908)
at java.nio.file.Files.copy(Files.java:3027) at
com.siemens.dynamowerk.lddocgen.webapp.controller.DocumentsController
.storeDocument(DocumentsController.java:62)
at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.springframework.web.method.support.InvocableHandlerMethod.doInvok
e(InvocableHandlerMethod.java:189)
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeF
orRequest(InvocableHandlerMethod.java:138)
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocabl
eHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingH
andlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingH
andlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:800)
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapt
er.handle(AbstractHandlerMethodAdapter.java:87)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(Dispatch
erServlet.java:1038)
at
org.springframework.web.servlet.DispatcherServlet.doService(Dispatche
rServlet.java:942)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(Frame
workServlet.java:1005)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServ
let.java:908)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkSer
vlet.java:882)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appl
icationFilterChain.java:231)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationF
ilterChain.java:166)
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52
)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appl
icationFilterChain.java:193)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationF
ilterChain.java:166)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperV
alve.java:199)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextV
alve.java:96)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(Authentica
torBase.java:610)
at
org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.j
ava:556)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.j
ava:140)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.j
ava:81)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAcce
ssLogValve.java:650)
at
org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:67
9)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineVal
ve.java:87)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.jav
a:342)
at
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java
:800)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLig
ht.java:66)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(Abstract
Protocol.java:806)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpo
int.java:2388)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBas
e.java:49)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.
java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskTh
read.java:61)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: Unexpected error [54] reading
data from the APR/native socket [45,112,807,584] with wrapper
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@70c3965:4511
2807584].
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.fillReadBuffe
r(AprEndpoint.java:2583)
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.fillReadBuffe
r(AprEndpoint.java:2503)
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.read(AprEndpo
int.java:2486)
The request itself:
$ time curl --data @inputs.zip -H "Content-Type:
application/zip"
https://sitex-ldadw.ad001.siemens.net/prod/api/documents
--verbose --negotiate -u : * Uses proxy env variable NO_PROXY ==
'localhost .siemens.net .siemens.com .siemens.de' * Trying
147.54.64.149:443... * TCP_NODELAY set * Connected to
sitex-ldadw.ad001.siemens.net (147.54.64.149) port 443 (#0) *
ALPN, offering h2 * ALPN, offering http/1.1 * successfully set
certificate verify locations: * CAfile:
/usr/local/etc/ssl/cert.pem CApath: none * TLSv1.3 (OUT), TLS
handshake, Client hello (1): * TLSv1.3 (IN), TLS handshake,
Server hello (2): * TLSv1.3 (IN), TLS handshake, Encrypted
Extensions (8): * TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15): * TLSv1.3 (IN),
TLS handshake, Finished (20): * TLSv1.3 (OUT), TLS change cipher,
Change cipher spec (1): * TLSv1.3 (OUT), TLS handshake, Finished
(20): * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384 *
ALPN, server accepted to use http/1.1 * Server certificate: *
subject: C=DE; O=Siemens; OU=LDA DW;
CN=sitex-ldadw.ad001.siemens.net * start date: Mar 19 13:10:13
2019 GMT * expire date: Mar 19 13:10:13 2020 GMT *
subjectAltName: host "sitex-ldadw.ad001.siemens.net" matched
cert's "sitex-ldadw.ad001.siemens.net" * issuer: C=DE;
ST=Bayern; L=Muenchen; O=Siemens; serialNumber=ZZZZZZB7;
OU=Siemens Trust Center; CN=Siemens Issuing CA Intranet Server
2017 * SSL certificate verify ok. * Server auth using Negotiate
with user ''
POST /prod/api/documents HTTP/1.1 Host:
sitex-ldadw.ad001.siemens.net Authorization: Negotiate
YIIRdQYGKwYB... User-Agent: curl/7.65.1 Accept: */*
Content-Type: application/zip Content-Length: 1036 Expect:
100-continue
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4): * TLSv1.3
(IN), TLS handshake, Newsession Ticket (4): * old SSL session ID
is stale, removing * Done waiting for 100-continue * We are
completely uploaded and fine
* Mark bundle as not supporting multiuse < HTTP/1.1 503 Proxy
Error < Date: Tue, 02 Jul 2019 13:30:21 GMT < Server:
Apache/2.4.39 (FreeBSD) OpenSSL/1.1.1a-freebsd
mod_auth_gssapi/1.6.1 < X-Frame-Options: SAMEORIGIN <
Content-Length: 425 < Connection: close < Content-Type:
text/html; charset=iso-8859-1 < <!DOCTYPE HTML PUBLIC
"-//IETF//DTD HTML 2.0//EN"> <html><head> <title>503 Proxy
Error</title> </head><body> <h1>Proxy Error</h1> <p>The server is
temporarily unable to service your request due to maintenance
downtime or capacity problems. Please try again later.</p> <hr>
<address>Apache/2.4.39 (FreeBSD) OpenSSL/1.1.1a-freebsd
mod_auth_gssapi/1.6.1 Server at sitex-ldadw.ad001.siemens.net
Port 443</address> </body></html> * Closing connection 0 *
TLSv1.3 (OUT), TLS alert, close notify (256):
real 1m0,175s user 0m0,047s sys 0m0,007s
Where can I start digging? Tomcat? HTTPd? Maybe I should run HTTPd
in debug mode for a day and analyze that?
What does:
$ perror 54
Give you? You're on BSD, right? [See below for C code to show that
message]
On Linux, that error code is "Exchange full" which makes no sense. On
my Mac, it says it's "Connection reset by peer" which makes much more
sense.
Same as on the Mac:
$ ./test 54
Error 54: Connection reset by peer
[2]
http://people.apache.org/~ylavic/patches/httpd-2.4.x-forward_100_conti
nue-v6.patch
What
happens if you run without the patch?
I ran initially without the patch months ago. Without it, HTTPd sends
100 immediately, making the client the data while Tomcat will reject
with 401. The client has to authenticate and reupload. So at worst, the
request requires twice as long.
See also the BZ issue and this log:
https://bz.apache.org/bugzilla/attachment.cgi?id=36016
What happens if you upload without the 100-Continue?
curl completely uploads the file, Tomcat rejects with 401 and curl tries
again with the SPNEGO ticket as well as the file again.
During your ~1min stall, Tomcat is still waiting for data, right? When
the connection fails, Tomcat drops its error message at the same time,
right? Can you post a stack trace of what the Tomcat thread is doing
at that time? I assume it's blocked on a read of some kind.
I need to check this with jstack. I'll get back to you as soon as possible.
BR,
Michael
Source for perror:
==== BEGIN perror.c ===
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
int main(int argc, char *argv[]) {
if(argc > 1) {
int code = (int)strtol(argv[1], NULL, 10);
printf("Error %d: %s\n", code, strerror(code));
} else {
fprintf(stderr, "Usage: %s code\n", argv[0]);
}
}
==== END perror.c ===
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl0bdeMACgkQHPApP6U8
pFgqxw//T4dxjjctSN1VDJsYIJ3gxtWHhaC7XnOhi0JZ2B07uSysUTFcXMA29I3v
OnX9d4w78+TEP+Ar53Yimf8Tyk3r/5vXQ0oN2pZXq4cHiirtVlnYDCWI7DNgHf+4
14tVVOibBaTjfo/ElsH8YRdyIPN0q8tik0N0znAKIOmHjpo+C8eVZEkNuAQhAxyu
nLGJGXPSKg4Yho/7AsAWGR2KDj9UPM1PLcSc3cL7d+FtRHZvgv4qovcUJUOVhKHQ
IvEuXMb/PwydQKNw1FxzZ87ieyWthwsTwZ63c9XWsLSOrNrvDLYqnuKNj7ZQGwSI
2ICIt/gYWAvn1PwXd5pWr2bwMN3IOTjMnd6HkdcS3mJRQ4N7dSaHSBn/Oy4qjuPn
9T+FQ/zASYMkU/jkHJm4u5nGY3bNvaK6J3R3rGda1oSqksHmwla/7eQ6olNUMrEb
hBP/+ZYTEHMGMr9GOOfLUSdfiUwMLHqThoFnDq3Be9BBeYIHcl0Xlt0l4srNh01Y
yjFKjk/D7ml7i9UrkDGSPe/jomXK5ASFkHi8scm95n7RvljHnpHpKoA6Iri3yCMr
qU0fLK6HIkbzBQW3ajkeLxfMVKMj0bTMDwdcsq+w4fVVvsKtfcMhOGgiqm5wMxD8
K/pWQUWgM+bdUaSU6lGbB1uFZCqicEgvOkHt40F17OlzDv9SYH8=
=Q/eG
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
