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 <[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 <[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]
