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 "Brooks, Kenneth S" <ke...@chase.com> on 2010/05/25 19:06:46 UTC

java.lang.IllegalStateException: Connection already open

What would cause this:  java.lang.IllegalStateException: Connection already open

Never saw this when using httpclient 3.x, recently upgraded to 4.0.1 and saw this a few times while running performance tests.

Here are all of the configurations used when constructing the client:
        HttpParams httpParams = new BasicHttpParams();

        HttpProtocolParams.setVersion(httpParams, HttpVersion.HTTP_1_1);

        ConnManagerParams.setMaxTotalConnections(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_TOTAL_CONNECTIONS));
        ConnManagerParams.setMaxConnectionsPerRoute(httpParams, new ConnPerRouteBean(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_CONNECTIONS_PER_ROUTE)));

        HttpConnectionParams.setConnectionTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_CONNECTION_TIMEOUT));
        HttpConnectionParams.setStaleCheckingEnabled(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_STALE_CONNECTION_CHECK_ENABLED));
        HttpConnectionParams.setSoTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SOCKET_TIMEOUT));
        HttpConnectionParams.setLinger(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SO_LINGER));
        HttpConnectionParams.setTcpNoDelay(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_TCP_NODELAY));

        SchemeRegistry schemeRegistry = new SchemeRegistry();
        schemeRegistry.register(new Scheme("http", PlainSocketFactory.getSocketFactory(), 80));

        ClientConnectionManager clientConnectionManager = new ThreadSafeClientConnManager(httpParams, schemeRegistry);

        IdleConnectionMonitorThread idleConnectionMonitorThread = new IdleConnectionMonitorThread(clientConnectionManager);
        idleConnectionMonitorThread.setIdleConnectionTimeout(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_TIMEOUT));
        idleConnectionMonitorThread.setIdleConnectionCheckInterval(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_CHECK_INTERVAL));
        idleConnectionMonitorThread.start();

        httpClient = new DefaultHttpClient(clientConnectionManager, httpParams);




This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Great. I'll see what can be dug out of the logs.

Oleg


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


RE: java.lang.IllegalStateException: Connection already openn

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Will do.. thank you so much for putting the effort into this.

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Wednesday, June 02, 2010 1:50 PM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already openn

On Wed, 2010-06-02 at 09:49 -0400, Brooks, Kenneth S wrote:
> Excellent.
> 
> 
> I just read the jira..
> 
> Since I'm on 4.0.x, when you say "For 4.0.x the problem can be worked around by retaining the pool lock for the entire span of the #closeIdleConnection."
> Is that something that I can do in my code, or will it require me to patch 4.0.x?
> Bear with me as I don't have the code open in front of me.
> 

Hi Ken

I just committed the work-around to the 4.0.x branch. You can check it
out, try out with your application, and let me know if that fixed the
issue for you:

http://svn.apache.org/repos/asf/httpcomponents/httpclient/branches/4.0.x/ 

Cheers

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already openn

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-06-02 at 09:49 -0400, Brooks, Kenneth S wrote:
> Excellent.
> 
> 
> I just read the jira..
> 
> Since I'm on 4.0.x, when you say "For 4.0.x the problem can be worked around by retaining the pool lock for the entire span of the #closeIdleConnection."
> Is that something that I can do in my code, or will it require me to patch 4.0.x?
> Bear with me as I don't have the code open in front of me.
> 

Hi Ken

I just committed the work-around to the 4.0.x branch. You can check it
out, try out with your application, and let me know if that fixed the
issue for you:

http://svn.apache.org/repos/asf/httpcomponents/httpclient/branches/4.0.x/ 

Cheers

Oleg


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Excellent.


I just read the jira..

Since I'm on 4.0.x, when you say "For 4.0.x the problem can be worked around by retaining the pool lock for the entire span of the #closeIdleConnection."
Is that something that I can do in my code, or will it require me to patch 4.0.x?
Bear with me as I don't have the code open in front of me.

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Wednesday, June 02, 2010 7:21 AM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Mon, 2010-05-31 at 22:39 -0400, Brooks, Kenneth S wrote:
> I would love to but its pretty unlikely that I'll be able to do it.. we see 1 or 2 of these in a 24 hour period.
> There are millions of calls to the server during that time but that is spread out among 16 (or more) client machines that are generating the load. 
> 
> I just realized that I misguided you a bit.. the server side is solaris10.. the client side is windows (which is where httpclient is running)
> I'll have to validate at work tomorrow if it is XP or something else.
> 
> 
> The only thing I can do is get them to possibly ramp up the volume from a particular machine to see if it makes the issue show up quicker.
> 
> -k
> 

Hi Ken

I think I have found a cause of the problem

https://issues.apache.org/jira/browse/HTTPCLIENT-948

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2010-05-31 at 22:39 -0400, Brooks, Kenneth S wrote:
> I would love to but its pretty unlikely that I'll be able to do it.. we see 1 or 2 of these in a 24 hour period.
> There are millions of calls to the server during that time but that is spread out among 16 (or more) client machines that are generating the load. 
> 
> I just realized that I misguided you a bit.. the server side is solaris10.. the client side is windows (which is where httpclient is running)
> I'll have to validate at work tomorrow if it is XP or something else.
> 
> 
> The only thing I can do is get them to possibly ramp up the volume from a particular machine to see if it makes the issue show up quicker.
> 
> -k
> 

Hi Ken

I think I have found a cause of the problem

https://issues.apache.org/jira/browse/HTTPCLIENT-948

Oleg


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
I would love to but its pretty unlikely that I'll be able to do it.. we see 1 or 2 of these in a 24 hour period.
There are millions of calls to the server during that time but that is spread out among 16 (or more) client machines that are generating the load. 

I just realized that I misguided you a bit.. the server side is solaris10.. the client side is windows (which is where httpclient is running)
I'll have to validate at work tomorrow if it is XP or something else.


The only thing I can do is get them to possibly ramp up the volume from a particular machine to see if it makes the issue show up quicker.

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Sunday, May 30, 2010 5:32 PM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Sun, 2010-05-30 at 17:23 -0400, Brooks, Kenneth S wrote:
> Solaris 10
> JDK should be 1.5.0_11 but I'll double check on Tuesday.
> 

Nasty. The problem seems to be platform specific. I am using Linux
(Ubuntu) and am unable to reproduce it locally.

Do you think you could put together a test case?

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Sun, 2010-05-30 at 17:23 -0400, Brooks, Kenneth S wrote:
> Solaris 10
> JDK should be 1.5.0_11 but I'll double check on Tuesday.
> 

Nasty. The problem seems to be platform specific. I am using Linux
(Ubuntu) and am unable to reproduce it locally.

Do you think you could put together a test case?

Oleg


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Solaris 10
JDK should be 1.5.0_11 but I'll double check on Tuesday.

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Sunday, May 30, 2010 4:51 PM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Ken,

I have not been able to reproduce the bug no matter what kind of
settings I tried. I have also been so far unable to figure out the cause
of the race condition just by looking at the code. I am running out of
ideas. What JVM version and what OS are you using?

Oleg  


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Ken,

I have not been able to reproduce the bug no matter what kind of
settings I tried. I have also been so far unable to figure out the cause
of the race condition just by looking at the code. I am running out of
ideas. What JVM version and what OS are you using?

Oleg  


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


RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-05-26 at 13:51 -0400, Brooks, Kenneth S wrote:
> When you say 'If you want to make sure persistent connections
> do not get stale, you can simply instruct HttpClient to not re-use
> connections that have been idle longer than, say, 20,000ms' are you referring to the 
> Connection Keep Alive strategy: http://hc.apache.org/httpcomponents-client-4.0.1/tutorial/html/connmgmt.html#d4e645
> 

Yes, this is exactly what I meant.

Oleg

> Or is there some param I can set on the connection/pool?
> 
> -k



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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
When you say 'If you want to make sure persistent connections
do not get stale, you can simply instruct HttpClient to not re-use
connections that have been idle longer than, say, 20,000ms' are you referring to the 
Connection Keep Alive strategy: http://hc.apache.org/httpcomponents-client-4.0.1/tutorial/html/connmgmt.html#d4e645

Or is there some param I can set on the connection/pool?

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Wednesday, May 26, 2010 1:05 PM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Ken

I took a cursory look at the log and even though I have not yet found
the cause of the race condition, I am at least pretty sure I know why it
has gone undetected for so long.

Your idle connection checks are waaaaay too aggressive. It is really
unnecessary to run the checks so often. Once a minute should be enough,
let alone every second. If you want to make sure persistent connections
do not get stale, you can simply instruct HttpClient to not re-use
connections that have been idle longer than, say, 20,000ms but actively
evict connections from the pool only once a minute or so.

The idle connection handler in your configuration puts unnecessary load
on the connection pool and degrades performance. 

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-05-26 at 13:31 -0400, Brooks, Kenneth S wrote:
> Ok.. I had the same gut feeling when I put that in back in the 3.1 era.. 
> 
> 1) going to go look for that configuration (instructing HttpClient not to use connections idle longer than 20,000ms).
> 2) change the idle to check each minute.. 
> 
> 
> Just to be safe.. 
> If I have a pool of 5 connections and tell it not to use connections idle longer than 20,000ms is there a chance I would run out of entries in the pool before they were evicted and refreshed? Will it just ignore the pool size and open new connections if all 5 connections are either active or idle longer than 20,000ms?
> 
> -k
> 

Ken,

No, there is not.The pooling connection manager is fairly clever about
persistent connections. When a connection being leased, the connection
manager will iterate through the list of available persistent
connections, pick up the first on,e which is still considered fresh when
available, and drop those connections that are no longer considered
re-usable. The connection manager will block the requesting thread only
if the maximum number of connection have been leased and are being used
for a request execution. The manager will throw an exception only if all
connections are being actively used and none has been released in time.
If there are idle connections in the pool, the manager is guaranteed to
return a valid connection, be it an existing connection, which is still
fresh, or a new one.

Oleg  


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Ok.. I had the same gut feeling when I put that in back in the 3.1 era.. 

1) going to go look for that configuration (instructing HttpClient not to use connections idle longer than 20,000ms).
2) change the idle to check each minute.. 


Just to be safe.. 
If I have a pool of 5 connections and tell it not to use connections idle longer than 20,000ms is there a chance I would run out of entries in the pool before they were evicted and refreshed? Will it just ignore the pool size and open new connections if all 5 connections are either active or idle longer than 20,000ms?

-k


-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Wednesday, May 26, 2010 1:05 PM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Ken

I took a cursory look at the log and even though I have not yet found
the cause of the race condition, I am at least pretty sure I know why it
has gone undetected for so long.

Your idle connection checks are waaaaay too aggressive. It is really
unnecessary to run the checks so often. Once a minute should be enough,
let alone every second. If you want to make sure persistent connections
do not get stale, you can simply instruct HttpClient to not re-use
connections that have been idle longer than, say, 20,000ms but actively
evict connections from the pool only once a minute or so.

The idle connection handler in your configuration puts unnecessary load
on the connection pool and degrades performance. 

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2010-05-26 at 11:01 -0400, Brooks, Kenneth S wrote:
> Attaching 2 log snippets.
> 
> First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411
> 
> The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.
> 
> FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.
> 

Ken

I took a cursory look at the log and even though I have not yet found
the cause of the race condition, I am at least pretty sure I know why it
has gone undetected for so long.

Your idle connection checks are waaaaay too aggressive. It is really
unnecessary to run the checks so often. Once a minute should be enough,
let alone every second. If you want to make sure persistent connections
do not get stale, you can simply instruct HttpClient to not re-use
connections that have been idle longer than, say, 20,000ms but actively
evict connections from the pool only once a minute or so.

The idle connection handler in your configuration puts unnecessary load
on the connection pool and degrades performance. 

Oleg


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Attaching 2 log snippets.

First is the httpclient log with log4j.logger.org.apache.http=TRACE, F as the log4j setting. I've included the very last line of the wire trace from the previous call.. just to give some conetext. I think what you are looking for is right around: 2010-05-22 16:41:03,411

The second is our client logs, just to show when the call was attempted and failed with the IllegalStateException.

FYI my idleconnectionhandler is running every 1000ms and evicting anything older than 20,000ms.

======== httpclient log =========
2010-05-22 16:40:42,864 DEBUG http.wire         (Wire.java:78)    - << "[EOL]"
2010-05-22 16:40:42,864 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:218)    - Released connection is reusable.
2010-05-22 16:40:42,864 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:366)    - Releasing connection [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]
2010-05-22 16:40:42,864 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:386)    - Pooling connection [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]; keep alive for -1 MILLISECONDS
2010-05-22 16:40:42,864 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:77)    - Adding connection at: 1274560842864
2010-05-22 16:40:42,864 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:619)    - Notifying no-one, there are no waiting threads
2010-05-22 16:40:43,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:43,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560843270
2010-05-22 16:40:43,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:43,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560823270
2010-05-22 16:40:44,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:44,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560844270
2010-05-22 16:40:44,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:44,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560824270
2010-05-22 16:40:45,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:45,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560845270
2010-05-22 16:40:45,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:45,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560825270
2010-05-22 16:40:46,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:46,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560846270
2010-05-22 16:40:46,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:46,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560826270
2010-05-22 16:40:47,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:47,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560847270
2010-05-22 16:40:47,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:47,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560827270
2010-05-22 16:40:48,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:48,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560848270
2010-05-22 16:40:48,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:48,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560828270
2010-05-22 16:40:49,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:49,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560849270
2010-05-22 16:40:49,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:49,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560829270
2010-05-22 16:40:50,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:50,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560850270
2010-05-22 16:40:50,270 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:50,270 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560830270
2010-05-22 16:40:51,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:51,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560851395
2010-05-22 16:40:51,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:51,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560831395
2010-05-22 16:40:52,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:52,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560852395
2010-05-22 16:40:52,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:52,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560832395
2010-05-22 16:40:53,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:53,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560853395
2010-05-22 16:40:53,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:53,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560833395
2010-05-22 16:40:54,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:54,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560854395
2010-05-22 16:40:54,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:54,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560834395
2010-05-22 16:40:55,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:55,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560855395
2010-05-22 16:40:55,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:55,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560835395
2010-05-22 16:40:56,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:56,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560856395
2010-05-22 16:40:56,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:56,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560836395
2010-05-22 16:40:57,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:57,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560857395
2010-05-22 16:40:57,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:57,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560837395
2010-05-22 16:40:58,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:58,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560858395
2010-05-22 16:40:58,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:58,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560838395
2010-05-22 16:40:59,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:40:59,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560859395
2010-05-22 16:40:59,395 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:40:59,395 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560839395
2010-05-22 16:41:00,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:00,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560860396
2010-05-22 16:41:00,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:00,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560840396
2010-05-22 16:41:01,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:01,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560861396
2010-05-22 16:41:01,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:01,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560841396
2010-05-22 16:41:02,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:02,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560862396
2010-05-22 16:41:02,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:02,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560842396
2010-05-22 16:41:03,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:03,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560863396
2010-05-22 16:41:03,396 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:03,396 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560843396
2010-05-22 16:41:03,411 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:168)    - ThreadSafeClientConnManager.getConnection: HttpRoute[{}->http://prf-services.mycompany.net:9810], timeout = 0
2010-05-22 16:41:03,411 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:129)    - Closing idle connection, connection time: 1274560842864
2010-05-22 16:41:03,411 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:153)    - Connection closed
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:281)    - Total connections kept alive: 1
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:282)    - Total issued connections: 0
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:283)    - Total allocated connection: 1 out of 5
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:428)    - Getting free connection [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]
2010-05-22 16:41:03,411 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:141)    - Connection shut down
2010-05-22 16:41:03,411 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:220)    - Released connection is not reusable.
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:366)    - Releasing connection [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]
2010-05-22 16:41:03,411 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:619)    - Notifying no-one, there are no waiting threads
2010-05-22 16:41:04,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:04,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560864427
2010-05-22 16:41:04,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:04,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560844427
2010-05-22 16:41:05,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:05,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560865427
2010-05-22 16:41:05,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:05,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560845427
2010-05-22 16:41:06,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:06,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560866427
2010-05-22 16:41:06,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:06,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560846427
2010-05-22 16:41:07,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:07,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560867427
2010-05-22 16:41:07,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:07,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560847427
2010-05-22 16:41:08,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:08,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560868427
2010-05-22 16:41:08,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:08,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560848427
2010-05-22 16:41:09,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:09,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560869427
2010-05-22 16:41:09,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:09,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560849427
2010-05-22 16:41:10,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:10,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560870427
2010-05-22 16:41:10,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:10,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560850427
2010-05-22 16:41:11,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:11,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560871427
2010-05-22 16:41:11,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:11,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560851427
2010-05-22 16:41:12,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:12,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560872427
2010-05-22 16:41:12,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:12,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560852427
2010-05-22 16:41:13,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:13,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560873427
2010-05-22 16:41:13,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:13,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560853427
2010-05-22 16:41:14,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:14,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560874427
2010-05-22 16:41:14,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:14,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560854427
2010-05-22 16:41:15,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:15,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560875427
2010-05-22 16:41:15,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:15,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560855427
2010-05-22 16:41:16,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:16,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560876427
2010-05-22 16:41:16,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:16,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560856427
2010-05-22 16:41:17,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:17,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560877427
2010-05-22 16:41:17,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:17,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560857427
2010-05-22 16:41:18,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:18,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560878427
2010-05-22 16:41:18,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:18,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560858427
2010-05-22 16:41:19,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:19,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560879427
2010-05-22 16:41:19,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:19,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560859427
2010-05-22 16:41:20,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:20,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560880427
2010-05-22 16:41:20,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:20,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560860427
2010-05-22 16:41:21,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:21,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560881427
2010-05-22 16:41:21,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:21,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560861427
2010-05-22 16:41:22,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:274)    - Closing expired connections
2010-05-22 16:41:22,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:144)    - Checking for expired connections, now: 1274560882427
2010-05-22 16:41:22,427 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:267)    - Closing connections idle for 20000 MILLISECONDS
2010-05-22 16:41:22,427 DEBUG conn.IdleConnectionHandler (IdleConnectionHandler.java:119)    - Checking for connections, idle timeout: 1274560862427
2010-05-22 16:41:22,568 DEBUG tsccm.ThreadSafeClientConnManager (ThreadSafeClientConnManager.java:168)    - ThreadSafeClientConnManager.getConnection: HttpRoute[{}->http://prf-services.mycompany.net:9810], timeout = 0
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:281)    - Total connections kept alive: 0
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:282)    - Total issued connections: 0
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:283)    - Total allocated connection: 0 out of 5
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:454)    - No free connections [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:300)    - Available capacity: 5 out of 5 [HttpRoute[{}->http://prf-services.mycompany.net:9810]][null]
2010-05-22 16:41:22,568 DEBUG tsccm.ConnPoolByRoute (ConnPoolByRoute.java:481)    - Creating new connection [HttpRoute[{}->http://prf-services.mycompany.net:9810]]
2010-05-22 16:41:22,568 DEBUG client.DefaultHttpClient (DefaultRequestDirector.java:481)    - Attempt 1 to execute request
2010-05-22 16:41:22,568 DEBUG conn.DefaultClientConnection (DefaultClientConnection.java:244)    - Sending request: POST /cms.rcts/2010.2.1R3/ccs/prf.lr/default/cdc/essd-remote/ HTTP/1.1
2010-05-22 16:41:22,568 DEBUG http.wire         (Wire.java:78)    - >> "POST /cms.rcts/2010.2.1R3/ccs/prf.lr/default/cdc/essd-remote/ HTTP/1.1[EOL]"



======= our client log ========
22-May-2010:16:41:03.396        scd2ntb216      main    INFO    IRetentionCasesService.createAuditInfo()                NA      Created correlation id[ltu068_scd2ntb216_-188e9680:128bb650277:-6e6d] for mChannel=test;mUserId=ltu068;mParentAuditId=null;correlationId=null;operatorId=null
22-May-2010:16:41:03.427        scd2ntb216      main    EXCEPTION       IRetentionCasesService.getIncentiveSequence             ltu068_scd2ntb216_-188e9680:128bb650277:-6e6d   SYSTEM_EXCEPTION[Error making call[Error executing Remote Method=[getIncentiveSequence] for Service Url=[http://prf-services.mycompany.net:9810/cms.rcts/2010.2.1R3/ccs/prf.lr/default/cdc] Exception=[java.lang.IllegalStateException: Connection already open.
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeWithConnectionTimeoutRetries(RemoteServiceExecutorImpl.java:159)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeRequest(RemoteServiceExecutorImpl.java:126)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(RemoteServiceProxy.java:50)
        at $Proxy2.getIncentiveSequence(Unknown Source)
        at com.ccs.cco.cms.rcts.client.cases.RetentionCasesRemotingDelegate.getIncentiveSequence(RetentionCasesRemotingDelegate.java:748)
        at Actions.action(Actions.java:2887)
]]]
com.fusa.ssg.SystemException: Error making call[Error executing Remote Method=[getIncentiveSequence] for Service Url=[http://prf-services.mycompany.net:9810/cms.rcts/2010.2.1R3/ccs/prf.lr/default/cdc] Exception=[java.lang.IllegalStateException: Connection already open.
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeWithConnectionTimeoutRetries(RemoteServiceExecutorImpl.java:159)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeRequest(RemoteServiceExecutorImpl.java:126)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(RemoteServiceProxy.java:50)
        at $Proxy2.getIncentiveSequence(Unknown Source)
        at com.ccs.cco.cms.rcts.client.cases.RetentionCasesRemotingDelegate.getIncentiveSequence(RetentionCasesRemotingDelegate.java:748)
        at Actions.action(Actions.java:2887)
]]
        at com.ccs.cco.cms.rcts.client.cases.RetentionCasesRemotingDelegate.getIncentiveSequence(RetentionCasesRemotingDelegate.java:763)
        at Actions.action(Actions.java:2887)
------------Wrapped Exception-----------
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error executing Remote Method=[getIncentiveSequence] for Service Url=[http://prf-services.mycompany.net:9810/cms.rcts/2010.2.1R3/ccs/prf.lr/default/cdc] Exception=[java.lang.IllegalStateException: Connection already open.
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeWithConnectionTimeoutRetries(RemoteServiceExecutorImpl.java:159)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.executeRequest(RemoteServiceExecutorImpl.java:126)
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(RemoteServiceProxy.java:50)
        at $Proxy2.getIncentiveSequence(Unknown Source)
        at com.ccs.cco.cms.rcts.client.cases.RetentionCasesRemotingDelegate.getIncentiveSequence(RetentionCasesRemotingDelegate.java:748)
        at Actions.action(Actions.java:2887)
]
        at com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(RemoteServiceProxy.java:53)
        at $Proxy2.getIncentiveSequence(Unknown Source)
        at com.ccs.cco.cms.rcts.client.cases.RetentionCasesRemotingDelegate.getIncentiveSequence(RetentionCasesRemotingDelegate.java:748)
        at Actions.action(Actions.java:2887)
22-May-2010:16:41:03.427        scd2ntb216      main    PERFORMANCEMONITOR      IRetentionCasesService.getIncentiveSequence       ClientId=test_2010.2.1R3 getIncentiveSequence call.   ltu068_scd2ntb216_-188e9680:128bb650277:-6e6d   31



-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org]
Sent: Wednesday, May 26, 2010 4:55 AM
To: HttpClient User Discussion
Subject: RE: java.lang.IllegalStateException: Connection already open

On Tue, 2010-05-25 at 16:31 -0400, Brooks, Kenneth S wrote:
> Oleg,
>
> 22-May-2010:07:56:19.310      scd2ntb215      main    EXCEPTION       AbunchOfOurInfo...      ltu068_scd2ntb215_-1c64b48c:128bb71b989:-73d0   SYSTEM_EXCEPTION[Error making call[Error executing Remote Method=[addIncentive] for Service Url=[http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
>       at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
>       at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
>       at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
> ]]]
> com.mycompany.SystemException: Error making call[Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
>       at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
>       at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
>       at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
> ------------Wrapped Exception-----------
> com.mycompany.RemoteServiceException: Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
>       at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
>       at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
>       at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
>       at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
>
> Can't reproduce it right now because we only saw it a couple of times (during a performance test).
> I do have wire traces on, didn't see anything in there..
> But I don't think I have context logging for connection management / request execution turned on.
> I'll see if I can get those on for the next test.
>
> -ken

Hi Ken

There is likely to be a race condition in the AbstractPoolEntry class,
triggered by a combination of the IdleConnectionMonitorThread and heavy
load. I will be trying to pinpoint it. A connection management / request
execution context log would be very helpful, though.

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Tue, 2010-05-25 at 16:31 -0400, Brooks, Kenneth S wrote:
> Oleg,
> 
> 22-May-2010:07:56:19.310	scd2ntb215	main	EXCEPTION	AbunchOfOurInfo...	ltu068_scd2ntb215_-1c64b48c:128bb71b989:-73d0	SYSTEM_EXCEPTION[Error making call[Error executing Remote Method=[addIncentive] for Service Url=[http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
> 	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
> 	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
> 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
> ]]]
> com.mycompany.SystemException: Error making call[Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
> 	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
> 	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
> 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
> ------------Wrapped Exception-----------
> com.mycompany.RemoteServiceException: Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
> 	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
> 	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
> 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
> 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
>       ....our code here
> 
> Can't reproduce it right now because we only saw it a couple of times (during a performance test).
> I do have wire traces on, didn't see anything in there.. 
> But I don't think I have context logging for connection management / request execution turned on.
> I'll see if I can get those on for the next test.
> 
> -ken

Hi Ken

There is likely to be a race condition in the AbstractPoolEntry class,
triggered by a combination of the IdleConnectionMonitorThread and heavy
load. I will be trying to pinpoint it. A connection management / request
execution context log would be very helpful, though.

Oleg


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


RE: java.lang.IllegalStateException: Connection already open

Posted by "Brooks, Kenneth S" <ke...@chase.com>.
Oleg,

22-May-2010:07:56:19.310	scd2ntb215	main	EXCEPTION	AbunchOfOurInfo...	ltu068_scd2ntb215_-1c64b48c:128bb71b989:-73d0	SYSTEM_EXCEPTION[Error making call[Error executing Remote Method=[addIncentive] for Service Url=[http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
      ....our code here
]]]
com.mycompany.SystemException: Error making call[Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
      ....our code here
------------Wrapped Exception-----------
com.mycompany.RemoteServiceException: Error executing Remote Method=[addIncentive] for Service Url=[ http://mymachine:9810/myurl] Exception=[java.lang.IllegalStateException: Connection already open.
	at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:135)
	at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:108)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:415)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:641)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:576)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:554)
      ....our code here

Can't reproduce it right now because we only saw it a couple of times (during a performance test).
I do have wire traces on, didn't see anything in there.. 
But I don't think I have context logging for connection management / request execution turned on.
I'll see if I can get those on for the next test.

-ken

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Tuesday, May 25, 2010 3:51 PM
To: HttpClient User Discussion
Subject: Re: java.lang.IllegalStateException: Connection already open

On Tue, 2010-05-25 at 13:06 -0400, Brooks, Kenneth S wrote:
> What would cause this:  java.lang.IllegalStateException: Connection already open
> 
> Never saw this when using httpclient 3.x, recently upgraded to 4.0.1 and saw this a few times while running performance tests.
> 
> Here are all of the configurations used when constructing the client:
>         HttpParams httpParams = new BasicHttpParams();
> 
>         HttpProtocolParams.setVersion(httpParams, HttpVersion.HTTP_1_1);
> 
>         ConnManagerParams.setMaxTotalConnections(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_TOTAL_CONNECTIONS));
>         ConnManagerParams.setMaxConnectionsPerRoute(httpParams, new ConnPerRouteBean(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_CONNECTIONS_PER_ROUTE)));
> 
>         HttpConnectionParams.setConnectionTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_CONNECTION_TIMEOUT));
>         HttpConnectionParams.setStaleCheckingEnabled(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_STALE_CONNECTION_CHECK_ENABLED));
>         HttpConnectionParams.setSoTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SOCKET_TIMEOUT));
>         HttpConnectionParams.setLinger(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SO_LINGER));
>         HttpConnectionParams.setTcpNoDelay(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_TCP_NODELAY));
> 
>         SchemeRegistry schemeRegistry = new SchemeRegistry();
>         schemeRegistry.register(new Scheme("http", PlainSocketFactory.getSocketFactory(), 80));
> 
>         ClientConnectionManager clientConnectionManager = new ThreadSafeClientConnManager(httpParams, schemeRegistry);
> 
>         IdleConnectionMonitorThread idleConnectionMonitorThread = new IdleConnectionMonitorThread(clientConnectionManager);
>         idleConnectionMonitorThread.setIdleConnectionTimeout(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_TIMEOUT));
>         idleConnectionMonitorThread.setIdleConnectionCheckInterval(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_CHECK_INTERVAL));
>         idleConnectionMonitorThread.start();
> 
>         httpClient = new DefaultHttpClient(clientConnectionManager, httpParams);
> 
> 

Kenneth,

Could you please at the very least post the complete exception stack
trace or try to reproduce the problem with the context logging for
connection management / request execution turned on? For details on
context logging see

http://hc.apache.org/httpcomponents-client-4.0.1/logging.html

Oleg


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


This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

Re: java.lang.IllegalStateException: Connection already open

Posted by Oleg Kalnichevski <ol...@apache.org>.
On Tue, 2010-05-25 at 13:06 -0400, Brooks, Kenneth S wrote:
> What would cause this:  java.lang.IllegalStateException: Connection already open
> 
> Never saw this when using httpclient 3.x, recently upgraded to 4.0.1 and saw this a few times while running performance tests.
> 
> Here are all of the configurations used when constructing the client:
>         HttpParams httpParams = new BasicHttpParams();
> 
>         HttpProtocolParams.setVersion(httpParams, HttpVersion.HTTP_1_1);
> 
>         ConnManagerParams.setMaxTotalConnections(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_TOTAL_CONNECTIONS));
>         ConnManagerParams.setMaxConnectionsPerRoute(httpParams, new ConnPerRouteBean(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_MAX_CONNECTIONS_PER_ROUTE)));
> 
>         HttpConnectionParams.setConnectionTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_CONNECTION_TIMEOUT));
>         HttpConnectionParams.setStaleCheckingEnabled(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_STALE_CONNECTION_CHECK_ENABLED));
>         HttpConnectionParams.setSoTimeout(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SOCKET_TIMEOUT));
>         HttpConnectionParams.setLinger(httpParams, ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_SO_LINGER));
>         HttpConnectionParams.setTcpNoDelay(httpParams, ClientPropertyLocator.getInstance().getBooleanProperty(ClientPropertyLocator.HTTP_TCP_NODELAY));
> 
>         SchemeRegistry schemeRegistry = new SchemeRegistry();
>         schemeRegistry.register(new Scheme("http", PlainSocketFactory.getSocketFactory(), 80));
> 
>         ClientConnectionManager clientConnectionManager = new ThreadSafeClientConnManager(httpParams, schemeRegistry);
> 
>         IdleConnectionMonitorThread idleConnectionMonitorThread = new IdleConnectionMonitorThread(clientConnectionManager);
>         idleConnectionMonitorThread.setIdleConnectionTimeout(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_TIMEOUT));
>         idleConnectionMonitorThread.setIdleConnectionCheckInterval(ClientPropertyLocator.getInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_CHECK_INTERVAL));
>         idleConnectionMonitorThread.start();
> 
>         httpClient = new DefaultHttpClient(clientConnectionManager, httpParams);
> 
> 

Kenneth,

Could you please at the very least post the complete exception stack
trace or try to reproduce the problem with the context logging for
connection management / request execution turned on? For details on
context logging see

http://hc.apache.org/httpcomponents-client-4.0.1/logging.html

Oleg


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