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 Shawn Heisey <ap...@elyograg.org> on 2015/09/03 18:57:00 UTC

Re: Getting SocketTimeoutException after a very short amount of time

On 8/31/2015 3:02 AM, Oleg Kalnichevski wrote:
> There likely to be something that sets SO_TIMEOUT to a lower value. You
> should be able to trace it by placing a breakpoint or good ol'
> System.out.println at this line:
> http://hc.apache.org/httpcomponents-core-4.4.x/httpcore/xref/org/apache/http/impl/BHttpConnectionBase.html#277

I added a line just before the existing line 277:

System.out.println("timeout debug: " + timeout);

I never did figure out how to pull httpcore into eclipse, so I initially
had a problem with tabs in the source from my editing escapade in
Notepad++.  After I fixed that, I got a new jar, which I put into my
project and installed on the server.  With lsof on the server, I can see
that the new jar (named httpcore-4.4.1-custom-with-println.jar) has been
used by Java, and the original file is NOT in use by that process.

I don't see anything in the file my start script creates by redirecting
stdout, though.  If everything were working right, shouldn't I see
output from setting the timeout in my own code?  I thought HttpClient
defaulted to zero (no timeout) if it wasn't specified ... was I wrong
about that?  Is BHttpConnectionBase used by the deprecated
classes/methods as well as the suggested ones?

Right now it is looking like there's a problem with SolrJ setting the
socket timeout.  I see code in our HttpClientUtil that does set the
timeout, so if this problem I'm suspecting is correct, either SolrJ is
doing it wrong or the deprecated classes aren't working right.

What thoughts do you have?  Perhaps I should be creating the HttpClient
objects using HC methods directly instead of the SolrJ helper class.

Thanks,
Shawn


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/4/2015 3:18 PM, Shawn Heisey wrote:
> On 9/4/2015 12:36 PM, Oleg Kalnichevski wrote:
>> There is nothing wrong with your code. Feel free to run it outside
>> Solr without any extra dependencies to make sure it works as intended.
>> I _strongly_ suspect there is an older version of HttpClient /
>> HttpCore on your classpath.
> 
> I'm willing to believe almost anything the evidence supports at this
> point, but I haven't seen anything to support that theory.

Closing out this discussion:

The problem turned out, unsurprisingly, to be a bug in my own code.  As
much as I hate to learn that I've done something wrong, I'm glad to see
that the problem is not in HttpClient, and therefore cannot affect other
people.

Part of my code creates a few threads to do indexing on multiple Solr
shards in parallel, then uses join() to wait for those threads.  The
code that uses join() was incorrect, and not waiting long enough.  The
main loop of my program continued on its merry way, unaware of the
problem, while one of those threads was running in the background,
eventually reaching socket timeout and sending an alarm email.

Now that I know where the problem is, I can come up with a solution.

Thanks,
Shawn


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/4/2015 12:36 PM, Oleg Kalnichevski wrote:
> There is nothing wrong with your code. Feel free to run it outside
> Solr without any extra dependencies to make sure it works as intended.
> I _strongly_ suspect there is an older version of HttpClient /
> HttpCore on your classpath.

I'm willing to believe almost anything the evidence supports at this
point, but I haven't seen anything to support that theory.

I will try to come up with a test program using HttpClient only that
calls one of our optimize URLs to see whether I get the same timeout. 
If it works as expected, I will take this problem to the Solr list.

The classpath calculation is simple.  Here's the "env.sh" that my start
script sources to set the classpath:

root@bigindy5:/opt/sparkbuild# cat env.sh
#!/bin/sh


for i in \
 -Xms4M \
 -Xmx1024M \
 -XX:+UseG1GC \
 -XX:+ParallelRefProcEnabled \
 -XX:G1HeapRegionSize=8m \
 -XX:MaxGCPauseMillis=200 \
 -XX:+UseLargePages \
 -XX:+AggressiveOpts \
# -Dcom.sun.management.jmxremote \
# -Dcom.sun.management.jmxremote.port=3001 \
# -Dcom.sun.management.jmxremote.ssl=false \
# -Dcom.sun.management.jmxremote.authenticate=false \

do
  OPTS="${OPTS} $i"
done
export OPTS

CLASSPATH="bin:resources"
for i in lib/*.jar
do
  CLASSPATH=${CLASSPATH}:${i}
done
export CLASSPATH

At the following URL is the entire "lsof" output for the running copy of
my program.  I only see one location for the HC jars.  They do show up
twice, but it's the same location each time.  The only change I made in
this output was to redact our domain name from the TCP entries.  Solr is
listening on 8982, which explains the connections to that port in
CLOSE_WAIT.

http://apaste.info/38Z

Separate from my apparent inability to get a socket timeout set, but
possibly related, I'm somewhat mystified by the fact that I get a socket
timeout exception after 30 seconds when typical Java and Linux defaults
are no socket timeout and the DEBUG entries from httpclient are saying
that the connection can be kept alive indefinitely.  I haven't changed
any timeout settings in the Ubuntu OS, so unless Ubuntu sets a default
socket timeout, I don't know where this is coming from.  The same thing
happens on the production servers running CentOS 6, and I have not set
any OS-level timeouts there either.

Thanks,
Shawn


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Fri, 2015-09-04 at 11:39 -0600, Shawn Heisey wrote:
> On 9/4/2015 7:53 AM, Oleg Kalnichevski wrote:
> > I added socket timeout logging to the 4.5.x branch and trunk
> >
> > http://svn.apache.org/r1701258
> >
> > I clearly those values logged when executing HttpClient examples. 
> 
> I abandoned my custom httpcore jar built from the 4.4.1 tag with the one
> line addition, pulled down the 4.5.x branch of httpclient, and built
> it.  I replaced httpclient-4.5.jar with httpclient-4.5.1-SNAPSHOT.jar,
> and verified that the commit you made was included in the source code
> that I checked out.
> 
> Because I am using slf4j which ultimately logs to log4j1, I do have the
> jcl-over-slf4j jar in my classpath, which should capture the commons
> logging that httpclient uses.  I put the following in my
> log4j.properties file:
> 
> log4j.logger.org.apache.http=DEBUG, file
> 
> During program startup (when I build the HttpClient objects), I do not
> see any logs from httpclient at all, but when it actually connects to
> Solr, I do see DEBUG logs.  Those debug logs do not include the "set
> socket timeout" log entry that you added.  One of the logs says this:
> 
> DEBUG - 2015-09-04 11:38:01.551;   262; 3; Connection [id: 1][route:
> {}->http://bigindy5.REDACTED.com:8982] can be kept alive indefinitely
> 
> I must be creating the client objects incorrectlyfor the "set socket
> timeout" message to never be logged.  So you don't have to go looking
> back through the thread, here is the code I'm using:
> 

There is nothing wrong with your code. Feel free to run it outside Solr
without any extra dependencies to make sure it works as intended.

I _strongly_ suspect there is an older version of HttpClient / HttpCore
on your classpath.

Oleg 


>     /* Trying out a new way of creating clients */
>     RequestConfig requestConfig = RequestConfig.custom()
>       .setSocketTimeout(900000)
>       .setConnectTimeout(15000)
>       .build();
>     httpClient = HttpClients.custom()
>       .setDefaultRequestConfig(requestConfig)
>       .setMaxConnPerRoute(300)
>       .setMaxConnTotal(5000)
>       .build();
>     RequestConfig optimizeRequestConfig = RequestConfig.custom()
>       .setSocketTimeout(7200000)
>       .setConnectTimeout(15000)
>       .build();
>     optimizeHttpClient = HttpClients.custom()
>       .setDefaultRequestConfig(optimizeRequestConfig)
>       .build();
> 
> Thanks,
> Shawn
> 
> 
> ---------------------------------------------------------------------
> 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: Getting SocketTimeoutException after a very short amount of time

Posted by Stefan Magnus Landrø <st...@gmail.com>.
Could you use SocketConfig?

Sendt fra min iPhone

> Den 4. sep. 2015 kl. 19.52 skrev Shawn Heisey <ap...@elyograg.org>:
> 
>> On 9/4/2015 11:39 AM, Shawn Heisey wrote:
>> I must be creating the client objects incorrectly for the "set socket
>> timeout" message to never be logged.
> 
> I checked the ClientConfiguration.java example, and found that it sets
> the socket timeout when it is building the HttpGet object, not the
> HttpClient object.
> 
> In my program, I have absolutely no control over the GET/POST requests,
> that is deep in the bowels of SolrJ.
> 
> As a committer on Lucene/Solr, I *do* have the ability to change SolrJ,
> and perhaps these parameters should be configured in our SolrClient
> object and actually set when the request objects are created, but I
> think it should be possible to set them on the HttpClient object and
> have all requests utilize those defaults.
> 
> Thanks,
> Shawn
> 
> 
> ---------------------------------------------------------------------
> 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: Getting SocketTimeoutException after a very short amount of time

Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/4/2015 11:39 AM, Shawn Heisey wrote:
> I must be creating the client objects incorrectly for the "set socket
> timeout" message to never be logged.

I checked the ClientConfiguration.java example, and found that it sets
the socket timeout when it is building the HttpGet object, not the
HttpClient object.

In my program, I have absolutely no control over the GET/POST requests,
that is deep in the bowels of SolrJ.

As a committer on Lucene/Solr, I *do* have the ability to change SolrJ,
and perhaps these parameters should be configured in our SolrClient
object and actually set when the request objects are created, but I
think it should be possible to set them on the HttpClient object and
have all requests utilize those defaults.

Thanks,
Shawn


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/4/2015 7:53 AM, Oleg Kalnichevski wrote:
> I added socket timeout logging to the 4.5.x branch and trunk
>
> http://svn.apache.org/r1701258
>
> I clearly those values logged when executing HttpClient examples. 

I abandoned my custom httpcore jar built from the 4.4.1 tag with the one
line addition, pulled down the 4.5.x branch of httpclient, and built
it.  I replaced httpclient-4.5.jar with httpclient-4.5.1-SNAPSHOT.jar,
and verified that the commit you made was included in the source code
that I checked out.

Because I am using slf4j which ultimately logs to log4j1, I do have the
jcl-over-slf4j jar in my classpath, which should capture the commons
logging that httpclient uses.  I put the following in my
log4j.properties file:

log4j.logger.org.apache.http=DEBUG, file

During program startup (when I build the HttpClient objects), I do not
see any logs from httpclient at all, but when it actually connects to
Solr, I do see DEBUG logs.  Those debug logs do not include the "set
socket timeout" log entry that you added.  One of the logs says this:

DEBUG - 2015-09-04 11:38:01.551;   262; 3; Connection [id: 1][route:
{}->http://bigindy5.REDACTED.com:8982] can be kept alive indefinitely

I must be creating the client objects incorrectlyfor the "set socket
timeout" message to never be logged.  So you don't have to go looking
back through the thread, here is the code I'm using:

    /* Trying out a new way of creating clients */
    RequestConfig requestConfig = RequestConfig.custom()
      .setSocketTimeout(900000)
      .setConnectTimeout(15000)
      .build();
    httpClient = HttpClients.custom()
      .setDefaultRequestConfig(requestConfig)
      .setMaxConnPerRoute(300)
      .setMaxConnTotal(5000)
      .build();
    RequestConfig optimizeRequestConfig = RequestConfig.custom()
      .setSocketTimeout(7200000)
      .setConnectTimeout(15000)
      .build();
    optimizeHttpClient = HttpClients.custom()
      .setDefaultRequestConfig(optimizeRequestConfig)
      .build();

Thanks,
Shawn


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Thu, 2015-09-03 at 13:13 -0600, Shawn Heisey wrote:
> On 9/3/2015 10:57 AM, Shawn Heisey wrote:
> > I don't see anything in the file my start script creates by
> > redirecting stdout, though. If everything were working right,
> > shouldn't I see output from setting the timeout in my own code?
> 
> I replaced the client construction using Solr's HttpClientUtil with the
> following, which I came up with after reading the
> ClientConfiguration.java example on the HC website:
> 
>   /* Trying out a new way of creating clients */
>   RequestConfig requestConfig = RequestConfig.custom()
>       .setSocketTimeout(900000)
>       .setConnectTimeout(15000)
>       .build();
>   httpClient = HttpClients.custom()
>       .setDefaultRequestConfig(requestConfig)
>       .setMaxConnPerRoute(300)
>       .setMaxConnTotal(5000)
>       .build();
>   RequestConfig optimizeRequestConfig = RequestConfig.custom()
>       .setSocketTimeout(7200000)
>       .setConnectTimeout(15000)
>       .build();
>   optimizeHttpClient = HttpClients.custom()
>       .setDefaultRequestConfig(optimizeRequestConfig)
>       .build();
> 
> The httpClient and optimizeHttpClient instances are defined like this:
> 
>   /**
>    * A static http client to use on Solr client objects.
>    */
>   private static HttpClient httpClient = null;
> 
>   /**
>    * A static http client to use on Solr client objects. This one is for
> doing
>    * optimizes, will use a much longer socket timeout.
>    */
>   private static HttpClient optimizeHttpClient = null;
> 
> I am still seeing nothing in stdout, even though there's an added
> System.out.println in BHttpResponseBase.java at the recommended location.
> 
> Am I doing something wrong in my attempts to debug this problem?
> 

Shawn

I added socket timeout logging to the 4.5.x branch and trunk

http://svn.apache.org/r1701258

I clearly those values logged when executing HttpClient examples. 

---
[DEBUG] RequestAddCookies - CookieSpec selected: default
[DEBUG] RequestAuthCache - Auth cache not set in the context
[DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {}->http://httpbin.org:80][total kept alive: 0; route allocated: 0 of 10; total allocated: 0 of 100]
[DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {}->http://httpbin.org:80][total kept alive: 0; route allocated: 1 of 10; total allocated: 1 of 100]
[DEBUG] MainClientExec - Opening connection {}->http://httpbin.org:80
[DEBUG] DefaultHttpClientConnectionOperator - Connecting to httpbin.org/54.175.219.8:80
[DEBUG] DefaultHttpClientConnectionOperator - Connection established 10.0.0.8:55361<->54.175.219.8:80
[DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 5000
[DEBUG] MainClientExec - Executing request GET /get HTTP/1.1
---

Oleg


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


Re: Getting SocketTimeoutException after a very short amount of time

Posted by Shawn Heisey <ap...@elyograg.org>.
On 9/3/2015 10:57 AM, Shawn Heisey wrote:
> I don't see anything in the file my start script creates by
> redirecting stdout, though. If everything were working right,
> shouldn't I see output from setting the timeout in my own code?

I replaced the client construction using Solr's HttpClientUtil with the
following, which I came up with after reading the
ClientConfiguration.java example on the HC website:

  /* Trying out a new way of creating clients */
  RequestConfig requestConfig = RequestConfig.custom()
      .setSocketTimeout(900000)
      .setConnectTimeout(15000)
      .build();
  httpClient = HttpClients.custom()
      .setDefaultRequestConfig(requestConfig)
      .setMaxConnPerRoute(300)
      .setMaxConnTotal(5000)
      .build();
  RequestConfig optimizeRequestConfig = RequestConfig.custom()
      .setSocketTimeout(7200000)
      .setConnectTimeout(15000)
      .build();
  optimizeHttpClient = HttpClients.custom()
      .setDefaultRequestConfig(optimizeRequestConfig)
      .build();

The httpClient and optimizeHttpClient instances are defined like this:

  /**
   * A static http client to use on Solr client objects.
   */
  private static HttpClient httpClient = null;

  /**
   * A static http client to use on Solr client objects. This one is for
doing
   * optimizes, will use a much longer socket timeout.
   */
  private static HttpClient optimizeHttpClient = null;

I am still seeing nothing in stdout, even though there's an added
System.out.println in BHttpResponseBase.java at the recommended location.

Am I doing something wrong in my attempts to debug this problem?

Thanks,
Shawn


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