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/conf/logging.properties
VersionLoggerListener.log Command line argument:
-Djava.security.auth.login.config=/usr/local/apache-tomcat-8.5/conf/login.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-ldap-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.8853348490257367125.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.8853348490257367125.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:45112807584].
at
org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:348)
at
org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:663)
at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:370)
at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.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(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:189)
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:800)
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1038)
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:908)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:882)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:610)
at
org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.java:556)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:679)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2388)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.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(TaskThread.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:45112807584].
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.fillReadBuffer(AprEndpoint.java:2583)
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.fillReadBuffer(AprEndpoint.java:2503)
at
org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.read(AprEndpoint.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?
Pointers greatly appreciated.
Regards,
Michael
[2]
http://people.apache.org/~ylavic/patches/httpd-2.4.x-forward_100_continue-v6.patch
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
