You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Pablo Caballero <pd...@gmail.com> on 2020/06/29 20:07:15 UTC

timeout not being honored while SSL handshake

Hi! I'm using httpclient to consume a rest service. Everything was (is)
working like a charm but we had an episode last week:

- After a short outage in our network (blaming this outage is an assumption
I can't confirm) we got 16 threads stuck in our app server on:

"[STUCK] ExecuteThread: '45' for queue: 'weblogic.kernel.Default
(self-tuning)'" #29841 daemon prio=1 os_prio=0 tid=0x00007f07ac1e1800
rc="DOMAIN" ac=2 nid=0x8c6d runnable [0x00007f077c1de000]
               java.lang.Thread.State: RUNNABLE
                at java.net.SocketInputStream.socketRead0(Native Method)
                at
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
                at
java.net.SocketInputStream.read(SocketInputStream.java:170)
                at
java.net.SocketInputStream.read(SocketInputStream.java:141)
                at
sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
                at sun.security.ssl.InputRecord.read(InputRecord.java:503)
                at
sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
                - locked <0x0000000093d38470> (a java.lang.Object)
                at
sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1375)
                - locked <0x0000000093d38530> (a java.lang.Object)
                at
sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1403)
                at
sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1387)
                at
org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayeredSocket(SSLConnectionSocketFactory.java:394)
                at
org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.upgrade(DefaultHttpClientConnectionOperator.java:185)
                at
org.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:369)
                at
org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:415)

- 16 was the value we used for defaultMaxPerRoute
(org.apache.http.impl.conn.PoolingHttpClientConnectionManager) so it makes
sense that we got 16
threads stuck.

- All subsequent threads trying to get a connection got an exception (after
X seconds with X equal to our value for connectionRequestTimeout) as
expected.

- I think I've narrowed the problem down to this part of the code
(MainClientExec class)

if (!managedConn.isOpen()) {
                this.log.debug("Opening connection " + route);
                try {
                                establishRoute(proxyAuthState, managedConn,
route, request, context);
                } catch (final TunnelRefusedException ex) {
                                if (this.log.isDebugEnabled()) {

this.log.debug(ex.getMessage());
                                }
                                response = ex.getResponse();
                                break;
                }
}

final int timeout = config.getSocketTimeout();
if (timeout >= 0) {
                managedConn.setSocketTimeout(timeout);
}

It seems like socket timeout is set after establishRoute so the SSL
handshake isn't affected by this setting.

I am right?

Could the connection timeout be passed down to this.connManager.upgrade
(inside establishRoute) in order to use
it as socket timeout while establishing the SSL connection?

Versions:

httpclient-4.5.jar
httpcore-4.4.1.jar
httpcore-nio-4.4.4.jar

Thank you very much!

Best regards

Re: timeout not being honored while SSL handshake

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2020-06-29 at 18:47 -0300, Pablo Caballero wrote:
> Hi Oleg! Thank you for your quick response!
> 
> We have NO explicit socket config settings in our application.
> 
> Today, while looking at the PoolingHttpClientConnectionManager class
> code I
> saw "something" called SocketConfig and I didn't dig further... :(
> 
> Now that you point it out I think I figured out what I should do (set
> a
> default socket config to my HttpClientBuilder, right?).
> 

Correct.

Oleg


> Thank you very much!
> 
> Best regards!
> 
> 
> 
> 
> On Mon, Jun 29, 2020 at 5:47 PM Oleg Kalnichevski <ol...@apache.org>
> wrote:
> 
> > On Mon, 2020-06-29 at 17:07 -0300, Pablo Caballero wrote:
> > > Hi! I'm using httpclient to consume a rest service. Everything
> > > was
> > > (is)
> > > working like a charm but we had an episode last week:
> > > 
> > > - After a short outage in our network (blaming this outage is an
> > > assumption
> > > I can't confirm) we got 16 threads stuck in our app server on:
> > > 
> > > "[STUCK] ExecuteThread: '45' for queue: 'weblogic.kernel.Default
> > > (self-tuning)'" #29841 daemon prio=1 os_prio=0
> > > tid=0x00007f07ac1e1800
> > > rc="DOMAIN" ac=2 nid=0x8c6d runnable [0x00007f077c1de000]
> > >                java.lang.Thread.State: RUNNABLE
> > >                 at java.net.SocketInputStream.socketRead0(Native
> > > Method)
> > >                 at
> > > java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > >                 at
> > > java.net.SocketInputStream.read(SocketInputStream.java:170)
> > >                 at
> > > java.net.SocketInputStream.read(SocketInputStream.java:141)
> > >                 at
> > > sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
> > >                 at
> > > sun.security.ssl.InputRecord.read(InputRecord.java:503)
> > >                 at
> > > sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
> > >                 - locked <0x0000000093d38470> (a
> > > java.lang.Object)
> > >                 at
> > > sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketI
> > > mpl.
> > > java:1375)
> > >                 - locked <0x0000000093d38530> (a
> > > java.lang.Object)
> > >                 at
> > > sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:
> > > 1403
> > > )
> > >                 at
> > > sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:
> > > 1387
> > > )
> > >                 at
> > > org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayered
> > > Sock
> > > et(SSLConnectionSocketFactory.java:394)
> > >                 at
> > > org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.upg
> > > rade
> > > (DefaultHttpClientConnectionOperator.java:185)
> > >                 at
> > > org.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgr
> > > ade(
> > > PoolingHttpClientConnectionManager.java:369)
> > >                 at
> > > org.apache.http.impl.execchain.MainClientExec.establishRoute(Main
> > > Clie
> > > ntExec.java:415)
> > > 
> > > - 16 was the value we used for defaultMaxPerRoute
> > > (org.apache.http.impl.conn.PoolingHttpClientConnectionManager) so
> > > it
> > > makes
> > > sense that we got 16
> > > threads stuck.
> > > 
> > > - All subsequent threads trying to get a connection got an
> > > exception
> > > (after
> > > X seconds with X equal to our value for connectionRequestTimeout)
> > > as
> > > expected.
> > > 
> > > - I think I've narrowed the problem down to this part of the code
> > > (MainClientExec class)
> > > 
> > > if (!managedConn.isOpen()) {
> > >                 this.log.debug("Opening connection " + route);
> > >                 try {
> > >                                 establishRoute(proxyAuthState,
> > > managedConn,
> > > route, request, context);
> > >                 } catch (final TunnelRefusedException ex) {
> > >                                 if (this.log.isDebugEnabled()) {
> > > 
> > > this.log.debug(ex.getMessage());
> > >                                 }
> > >                                 response = ex.getResponse();
> > >                                 break;
> > >                 }
> > > }
> > > 
> > > final int timeout = config.getSocketTimeout();
> > > if (timeout >= 0) {
> > >                 managedConn.setSocketTimeout(timeout);
> > > }
> > > 
> > > It seems like socket timeout is set after establishRoute so the
> > > SSL
> > > handshake isn't affected by this setting.
> > > 
> > > I am right?
> > 
> > You are right. This is expected. `RequestConfig` settings apply to
> > the
> > request execution and the response processing. They do not apply to
> > the
> > route negotiation. What are your `SocketConfig` settings?
> > 
> > Oleg
> > 
> > 
> > 
> > -----------------------------------------------------------------
> > ----
> > To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> > For additional commands, e-mail: 
> > httpclient-users-help@hc.apache.org
> > 
> > 


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: timeout not being honored while SSL handshake

Posted by Pablo Caballero <pd...@gmail.com>.
Hi Oleg! Thank you for your quick response!

We have NO explicit socket config settings in our application.

Today, while looking at the PoolingHttpClientConnectionManager class code I
saw "something" called SocketConfig and I didn't dig further... :(

Now that you point it out I think I figured out what I should do (set a
default socket config to my HttpClientBuilder, right?).

Thank you very much!

Best regards!




On Mon, Jun 29, 2020 at 5:47 PM Oleg Kalnichevski <ol...@apache.org> wrote:

> On Mon, 2020-06-29 at 17:07 -0300, Pablo Caballero wrote:
> > Hi! I'm using httpclient to consume a rest service. Everything was
> > (is)
> > working like a charm but we had an episode last week:
> >
> > - After a short outage in our network (blaming this outage is an
> > assumption
> > I can't confirm) we got 16 threads stuck in our app server on:
> >
> > "[STUCK] ExecuteThread: '45' for queue: 'weblogic.kernel.Default
> > (self-tuning)'" #29841 daemon prio=1 os_prio=0 tid=0x00007f07ac1e1800
> > rc="DOMAIN" ac=2 nid=0x8c6d runnable [0x00007f077c1de000]
> >                java.lang.Thread.State: RUNNABLE
> >                 at java.net.SocketInputStream.socketRead0(Native
> > Method)
> >                 at
> > java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> >                 at
> > java.net.SocketInputStream.read(SocketInputStream.java:170)
> >                 at
> > java.net.SocketInputStream.read(SocketInputStream.java:141)
> >                 at
> > sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
> >                 at
> > sun.security.ssl.InputRecord.read(InputRecord.java:503)
> >                 at
> > sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
> >                 - locked <0x0000000093d38470> (a java.lang.Object)
> >                 at
> > sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.
> > java:1375)
> >                 - locked <0x0000000093d38530> (a java.lang.Object)
> >                 at
> > sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1403
> > )
> >                 at
> > sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1387
> > )
> >                 at
> > org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayeredSock
> > et(SSLConnectionSocketFactory.java:394)
> >                 at
> > org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.upgrade
> > (DefaultHttpClientConnectionOperator.java:185)
> >                 at
> > org.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(
> > PoolingHttpClientConnectionManager.java:369)
> >                 at
> > org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClie
> > ntExec.java:415)
> >
> > - 16 was the value we used for defaultMaxPerRoute
> > (org.apache.http.impl.conn.PoolingHttpClientConnectionManager) so it
> > makes
> > sense that we got 16
> > threads stuck.
> >
> > - All subsequent threads trying to get a connection got an exception
> > (after
> > X seconds with X equal to our value for connectionRequestTimeout) as
> > expected.
> >
> > - I think I've narrowed the problem down to this part of the code
> > (MainClientExec class)
> >
> > if (!managedConn.isOpen()) {
> >                 this.log.debug("Opening connection " + route);
> >                 try {
> >                                 establishRoute(proxyAuthState,
> > managedConn,
> > route, request, context);
> >                 } catch (final TunnelRefusedException ex) {
> >                                 if (this.log.isDebugEnabled()) {
> >
> > this.log.debug(ex.getMessage());
> >                                 }
> >                                 response = ex.getResponse();
> >                                 break;
> >                 }
> > }
> >
> > final int timeout = config.getSocketTimeout();
> > if (timeout >= 0) {
> >                 managedConn.setSocketTimeout(timeout);
> > }
> >
> > It seems like socket timeout is set after establishRoute so the SSL
> > handshake isn't affected by this setting.
> >
> > I am right?
>
> You are right. This is expected. `RequestConfig` settings apply to the
> request execution and the response processing. They do not apply to the
> route negotiation. What are your `SocketConfig` settings?
>
> Oleg
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
>

Re: timeout not being honored while SSL handshake

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2020-06-29 at 17:07 -0300, Pablo Caballero wrote:
> Hi! I'm using httpclient to consume a rest service. Everything was
> (is)
> working like a charm but we had an episode last week:
> 
> - After a short outage in our network (blaming this outage is an
> assumption
> I can't confirm) we got 16 threads stuck in our app server on:
> 
> "[STUCK] ExecuteThread: '45' for queue: 'weblogic.kernel.Default
> (self-tuning)'" #29841 daemon prio=1 os_prio=0 tid=0x00007f07ac1e1800
> rc="DOMAIN" ac=2 nid=0x8c6d runnable [0x00007f077c1de000]
>                java.lang.Thread.State: RUNNABLE
>                 at java.net.SocketInputStream.socketRead0(Native
> Method)
>                 at
> java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
>                 at
> java.net.SocketInputStream.read(SocketInputStream.java:170)
>                 at
> java.net.SocketInputStream.read(SocketInputStream.java:141)
>                 at
> sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
>                 at
> sun.security.ssl.InputRecord.read(InputRecord.java:503)
>                 at
> sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
>                 - locked <0x0000000093d38470> (a java.lang.Object)
>                 at
> sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.
> java:1375)
>                 - locked <0x0000000093d38530> (a java.lang.Object)
>                 at
> sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1403
> )
>                 at
> sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1387
> )
>                 at
> org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayeredSock
> et(SSLConnectionSocketFactory.java:394)
>                 at
> org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.upgrade
> (DefaultHttpClientConnectionOperator.java:185)
>                 at
> org.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(
> PoolingHttpClientConnectionManager.java:369)
>                 at
> org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClie
> ntExec.java:415)
> 
> - 16 was the value we used for defaultMaxPerRoute
> (org.apache.http.impl.conn.PoolingHttpClientConnectionManager) so it
> makes
> sense that we got 16
> threads stuck.
> 
> - All subsequent threads trying to get a connection got an exception
> (after
> X seconds with X equal to our value for connectionRequestTimeout) as
> expected.
> 
> - I think I've narrowed the problem down to this part of the code
> (MainClientExec class)
> 
> if (!managedConn.isOpen()) {
>                 this.log.debug("Opening connection " + route);
>                 try {
>                                 establishRoute(proxyAuthState,
> managedConn,
> route, request, context);
>                 } catch (final TunnelRefusedException ex) {
>                                 if (this.log.isDebugEnabled()) {
> 
> this.log.debug(ex.getMessage());
>                                 }
>                                 response = ex.getResponse();
>                                 break;
>                 }
> }
> 
> final int timeout = config.getSocketTimeout();
> if (timeout >= 0) {
>                 managedConn.setSocketTimeout(timeout);
> }
> 
> It seems like socket timeout is set after establishRoute so the SSL
> handshake isn't affected by this setting.
> 
> I am right?

You are right. This is expected. `RequestConfig` settings apply to the
request execution and the response processing. They do not apply to the
route negotiation. What are your `SocketConfig` settings?

Oleg



---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org