On Fri, 2019-03-29 at 12:06 -0700, Mark Cafaro wrote:
> It then eventually times out when my socket timeout is reached:
>
>
This clearly suggests that the server fails to send a response back to
the client, so this looks like a server side issue to me.
Oleg
>
> 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 <m...@acafaro.com
> > 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 <m...@acafaro.com
> > 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:
> o...@ok2consulting.com> 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:ol...@apache.org> 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:ol...@apache.org> 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:httpclient-users-unsubscr...@hc.apache.org
> > >
> > > For additional commands, e-mail: mailto:
> > > mailto:mailto:httpclient-users-h...@hc.apache.org
> >
> >
> >
> >
> >
> > -----------------------------------------------------------------
> > --
> > --
> >
> > To unsubscribe, e-mail: mailto:
> > mailto:httpclient-users-unsubscr...@hc.apache.org
> >
> > For additional commands, e-mail: mailto:
> > mailto:httpclient-users-h...@hc.apache.org
>
>
>
>
>
> -------------------------------------------------------------------
> --
>
> To unsubscribe, e-mail: mailto:
> httpclient-users-unsubscr...@hc.apache.org
>
> For additional commands, e-mail: mailto:
> httpclient-users-h...@hc.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
