I've come up with two theories. In addition to this long running request, I have another thread making short requests frequently (every second).
1) Perhaps Travis CI is identifying my program as a spam bot given that it's making so many requests, and therefore blocking the response of my long running request. However, my short running requests always get their response so I'm not sure this makes sense. 2) Is it possible I'm running out of sockets or something? I use separate connection managers for the long running request and the short-frequent requests. ---- On Fri, 29 Mar 2019 12:06:06 -0700 Mark Cafaro <[email protected]> wrote ---- It then eventually times out when my socket timeout is reached: 2019-03-29 19:03:42,884 DEBUG [org.apache.http.wire] http-outgoing-0 << "[read] I/O error: Read timed out" 2019-03-29 19:03:42,884 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] http-outgoing-0: Close connection 2019-03-29 19:03:42,885 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] http-outgoing-0: Shutdown connection 2019-03-29 19:03:42,885 DEBUG [org.apache.http.impl.execchain.MainClientExec] Connection discarded 2019-03-29 19:03:42,886 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] Connection released: [id: 0][route: {s}->https://ci.company.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] 2019-03-29 19:03:42,886 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] Connection manager is shutting down 2019-03-29 19:03:42,886 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] Connection manager shut down ---- On Fri, 29 Mar 2019 11:56:49 -0700 Mark Cafaro <mailto:[email protected]> wrote ---- The wire log didn't reveal much. It doesn't output anything after getting stuck on httpclient.execute(). See below (I replaced sensitive names, IPs, and JSON with generic info): 2019-03-29 18:31:41,815 DEBUG [com.company.ci.Client] Executing post... 2019-03-29 18:31:42,254 DEBUG [org.apache.http.client.protocol.RequestAddCookies] CookieSpec selected: default 2019-03-29 18:31:42,263 DEBUG [org.apache.http.client.protocol.RequestAuthCache] Auth cache not set in the context 2019-03-29 18:31:42,265 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] Connection request: [route: {s}->https://ci.company.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] 2019-03-29 18:31:42,276 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] Connection leased: [id: 0][route: {s}->https://ci.company.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20] 2019-03-29 18:31:42,277 DEBUG [org.apache.http.impl.execchain.MainClientExec] Opening connection {s}->https://ci.company.com:443 2019-03-29 18:31:42,301 DEBUG [org.apache.http.impl.conn.DefaultHttpClientConnectionOperator] Connecting to ci.company.com/1.2.3.4:443 2019-03-29 18:31:42,301 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] Connecting socket to ci.company.com/1.2.3.4:443 with timeout 300000 2019-03-29 18:31:42,480 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2] 2019-03-29 18:31:42,484 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] 2019-03-29 18:31:42,486 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] Starting handshake 2019-03-29 18:31:42,715 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] Secure session established 2019-03-29 18:31:42,716 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] negotiated protocol: TLSv1.2 2019-03-29 18:31:42,716 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 2019-03-29 18:31:42,717 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] peer principal: CN=*.company.com, OU=EPS DevOps, O="Company, Inc.", L=Town, ST=ST, C=US 2019-03-29 18:31:42,717 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] peer alternative names: [*.company.com, company.com] 2019-03-29 18:31:42,718 DEBUG [org.apache.http.conn.ssl.SSLConnectionSocketFactory] issuer principal: CN=DigiCert SHA2 High Assurance Server CA, OU=http://www.digicert.com, O=DigiCert Inc, C=US 2019-03-29 18:31:42,721 DEBUG [org.apache.http.impl.conn.DefaultHttpClientConnectionOperator] Connection established 10.30.3.201:42816<->1.2.3.4:443 2019-03-29 18:31:42,721 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] http-outgoing-0: set socket timeout to 1920000 2019-03-29 18:31:42,722 DEBUG [org.apache.http.impl.execchain.MainClientExec] Executing request POST /services/json HTTP/1.1 2019-03-29 18:31:42,722 DEBUG [org.apache.http.impl.execchain.MainClientExec] Target auth state: UNCHALLENGED 2019-03-29 18:31:42,722 DEBUG [org.apache.http.impl.execchain.MainClientExec] Proxy auth state: UNCHALLENGED 2019-03-29 18:31:42,723 DEBUG [org.apache.http.headers] http-outgoing-0 >> POST /services/json HTTP/1.1 2019-03-29 18:31:42,729 DEBUG [org.apache.http.headers] http-outgoing-0 >> Content-Length: 87371 2019-03-29 18:31:42,730 DEBUG [org.apache.http.headers] http-outgoing-0 >> Content-Type: text/plain; charset=UTF-8 2019-03-29 18:31:42,730 DEBUG [org.apache.http.headers] http-outgoing-0 >> Host: ci.company.com 2019-03-29 18:31:42,730 DEBUG [org.apache.http.headers] http-outgoing-0 >> Connection: Keep-Alive 2019-03-29 18:31:42,730 DEBUG [org.apache.http.headers] http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_151) 2019-03-29 18:31:42,730 DEBUG [org.apache.http.headers] http-outgoing-0 >> Accept-Encoding: gzip,deflate 2019-03-29 18:31:42,730 DEBUG [org.apache.http.wire] http-outgoing-0 >> "POST /services/json HTTP/1.1[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "Content-Length: 87371[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "Content-Type: text/plain; charset=UTF-8[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "Host: ci.company.com[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_151)[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" 2019-03-29 18:31:42,731 DEBUG [org.apache.http.wire] http-outgoing-0 >> "[\r][\n]" 2019-03-29 18:31:42,740 DEBUG [org.apache.http.wire] http-outgoing-0 >> "{JSON_HERE}" ---- On Fri, 29 Mar 2019 08:57:41 -0700 Mark Cafaro <mailto:[email protected]> wrote ---- No exception. It just stays stuck on the httpclient.execute() line. I'll gather the wire logs. ---- On Fri, 29 Mar 2019 08:44:02 -0700 Oleg Kalnichevski <mailto:[email protected]> wrote ---- On Fri, 2019-03-29 at 08:37 -0700, Mark Cafaro wrote: > I mean to say when I'm using the Apache client, I see the server > sends back a proper response but the client never receives it (it > just stays stuck on httpclient.execute()). So, on the server side, > irrespective of the execution path it is taking, I ultimately know > it is sending back a response. Why the client is not reacting to that > response is the head scratcher. > What means "not reacting to that response"? This makes no sense. Does it throw an exception of any sort? Oleg > > > -Mark > > > > > ---- On Fri, 29 Mar 2019 08:12:34 -0700 Oleg Kalnichevski < > mailto:[email protected]> wrote ---- > > > > On Fri, 2019-03-29 at 08:09 -0700, Mark Cafaro wrote: > > > What makes me think it's a client side issue is that I can take > > the > > same request and run it with cURL and properly receive a response. > > I > > can also view the logs on the server side and see that a response > > was > > sent back. > > > > > > > > So what? That means absolutely nothing. Clients can behave > differently > > enough to trigger a different execution path on the server side. > > > > Oleg > > > > > > > I'll try turning on wire logging and see if that gives me any > > clues. > > Thanks. > > > > > > > > > > ---- On Fri, 29 Mar 2019 06:38:45 -0700 Oleg Kalnichevski < > > mailto:mailto:[email protected]> wrote ---- > > > > > > > > On Fri, 2019-03-29 at 06:34 -0700, Mark Cafaro wrote: > > > > > The call to httpclient.execute() is just stuck until the > > > eventual > > > socket timeout is reached. > > > > > > > > > > > > > > What makes you think this is a client side issue? Have you tried > > > > running your application with HttpClient wire logging turned out > > and > > > > analyzing data packets sent on the wire? > > > > > > > > Oleg > > > > > > > > > > > > > > > > -Mark > > > > > > > > > > > > P.S. Sorry if this created a new thread. I did not subscribe in > > > time > > > to get the first reply. > > > > > > > > > > What exactly do you mean by "never receives a response"? What > > > > happens > > > > instead? > > > > > > > > Oleg > > > > > > > > > Hi, > > > > > > > > > > I am running long HTTP post requests on Travis CI (Ubuntu > > > > > 14.04) > > > > > using the Apache HTTP Client. Strangely if a request exceeds > > > > > about 8 > > > > > minutes, the client never receives a response. I can see on > > > > > the > > > > > server side, however, that a response was sent back. I have > > > > > the > > > > > socket timeout set way beyond 8 minutes. > > > > > > > > > > If I perform the exact same request, on the exact same > > > > > machine, > > > > > using > > > > > cURL however, it works as expected (i.e. cURL receives a > > > > > response). > > > > > Also, if I perform the exact same request using the Apache > > > > > HTTP > > > > > Client on my local machine, it works as expected. > > > > > > > > > > I've tried playing around with sysctl > > > > > net.ipv4.tcp_keepalive_time, tcp_keepalive_intvl, > > > > > and tcp_keepalive_probes but they haven't solved the issue. > > > > > > > > > > Are there any settings in the Apache HTTP Client that may be > > > > > relevant > > > > > to this issue? > > > > > > > > > > Thanks, > > > > > > > > > > Mark > > > > > > > > > > > > ----------------------------------------------------------------- > > -- > > -- > > > > To unsubscribe, e-mail: mailto: > > mailto:mailto:[email protected] > > > > For additional commands, e-mail: mailto: > > mailto:mailto:[email protected] > > > > > > ------------------------------------------------------------------- > -- > > To unsubscribe, e-mail: mailto: > mailto:[email protected] > > For additional commands, e-mail: mailto: > mailto:[email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: mailto:[email protected] For additional commands, e-mail: mailto:[email protected]
