-----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. > [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? What happens if you upload without the 100-Continue? 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. - -chris 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
