[
https://issues.apache.org/jira/browse/HTTPCLIENT-747?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12578994#action_12578994
]
Sam Berlin commented on HTTPCLIENT-747:
---------------------------------------
We're still being hit by this in the
'httpclient-4.0-alpha4-20080303.184117-1.jar' snapshot, so I sleuthed around to
see what I could dig up.
I added some debugging log-statements into the code and was able to retrigger
the bug. This is what printed:
--
1968 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Requesting from: http://one.ip.address.and:port/request-uri
1968 DEBUG [PushProxy Requests] tsccm.RouteSpecificPool.createdEntry -
Creating an entry (will be: 1) for route:
HttpRoute[{}->http://one.ip.address.and:port], 18818235
3968 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Requesting from: http://one.ip.address.and:port/request-uri
3968 DEBUG [PushProxy Requests] tsccm.RouteSpecificPool.createdEntry -
Creating an entry (will be: 2) for route:
HttpRoute[{}->http://one.ip.address.and:port], 18818235
6968 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Request finished: http://one.ip.address.and:port/request-uri
8609 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Requesting from: http://one.ip.address.and:port/another-uri
8968 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Request finished: http://one.ip.address.and:port/request-uri
13968 DEBUG [Timer-0] http.DefaultHttpExecutor.shutdown - Aborting request to:
http://one.ip.address.and:port/another-uri
33203 DEBUG [EMAIL PROTECTED]@1e081c5] tsccm.RouteSpecificPool.dropEntry -
Dropping an entry (will be: 1) for route:
HttpRoute[{}->http://one.ip.address.and:port], 18818235
33203 DEBUG [EMAIL PROTECTED]@1e081c5] tsccm.RouteSpecificPool.dropEntry -
Dropping an entry (will be: 0) for route:
HttpRoute[{}->http://one.ip.address.and:port], 18818235
33218 DEBUG [PushProxy Requests] tsccm.RouteSpecificPool.createdEntry -
Creating an entry (will be: 1) for route:
HttpRoute[{}->http://one.ip.address.and:port], 18818235
33828 DEBUG [PushProxy Requests] tsccm.RouteSpecificPool.freeEntry - Freeing
an entry for route: HttpRoute[{}->http://one.ip.address.and:port], 33212367
java.lang.IllegalStateException: No entry created for this pool.
HttpRoute[{}->http://one.ip.address.and:port]
at
org.apache.http.impl.conn.tsccm.RouteSpecificPool.freeEntry(RouteSpecificPool.java:142)
at
org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry(ConnPoolByRoute.java:337)
at
org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection(ThreadSafeClientConnManager.java:230)
at
org.apache.http.impl.client.DefaultClientRequestDirector.execute(DefaultClientRequestDirector.java:427)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:500)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:455)
at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:421)
at
com.limegroup.gnutella.http.DefaultHttpExecutor.performRequest(DefaultHttpExecutor.java:102)
at
com.limegroup.gnutella.http.DefaultHttpExecutor.access$0(DefaultHttpExecutor.java:93)
at
com.limegroup.gnutella.http.DefaultHttpExecutor$MultiRequestor.run(DefaultHttpExecutor.java:146)
at
org.limewire.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1006)
at
org.limewire.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:549)
at java.lang.Thread.run(Unknown Source)
33828 DEBUG [PushProxy Requests] http.DefaultHttpExecutor.performRequest -
Request finished: http://one.ip.address.and:port/another-uri
--
Keep in that that (for better or worse) every method execution is done with a
different instance of HttpClient. Also note that more than 1 thread is named
"PushProxy Requests", so don't be confused thinking that's all one thread.
This is what the lines in the logs mean:
DefaultHttpExecutor.performRequest with "Requesting from":
HttpClient.execute(HttpUriRequest) is about to be called.
DefaultHttpExecutor.performRequest with "Requested finished": after
HttpClient.execute(HttpUriRequest) has returned.
RouteSpecificPool.createdEntry: createdEntry is called with the given route.
The "will be" number is what numEntries will increment too. The number at the
end after the comma is System.identityHashcode of the RouteSpecificPool object.
DefaultHttpExecutor.shutdown: HttpUriRequest.abort() is about to be called.
RouteSpecificPool.dropEntry: dropEntry is called with the given route. The
"will be" is what numEntries will decrement too, and the number after the comma
is the identityhashcode of RouteSpecificPool.
RouteSpecificPool.freeEntry: freeEntry is called with the given route. The
number after the gonna is the identityhashcode of the RouteSpecificPool.
Things that confuse me:
- Why did it take so long between the 8609 request for 'another-uri' till the
33218 createdEntry? Could a delay in connecting at the socket-level cause
this? Are the two entries even related?
- If the request was aborted (at 13968), why did it still try to to create an
entry (@ 33218), and what could cause the long delay?
- Why is the identityhashcode for the 33828 freeEntry different from the
identityhashcode of every other RouteSpecificPool?
There were connections to other hosts intermingled in the logs, but I stripped
those out. If they're useful for debugging, let me know and I can attach the
whole thing.
Let me know if there's other things that could be useful, and I'll try to
recreate this again. If I can figure out what can cause those log statements
to be printed out, I should be able to reproduce this more easily.
> No entry created for this pool.
> -------------------------------
>
> Key: HTTPCLIENT-747
> URL: https://issues.apache.org/jira/browse/HTTPCLIENT-747
> Project: HttpComponents HttpClient
> Issue Type: Bug
> Components: HttpConn
> Affects Versions: 4.0 Alpha 3
> Reporter: Roland Weber
> Priority: Minor
> Fix For: 4.0 Alpha 4
>
>
> Followup to https://issues.apache.org/jira/browse/HTTPCLIENT-741, as reported
> by Sam Berlin:
> java.lang.IllegalStateException: No entry created for this pool.
> HttpRoute[{}->http://74.160.66.42:14561]
> at
> org.apache.http.impl.conn.tsccm.RouteSpecificPool.freeEntry(RouteSpecificPool.java:137)
> at
> org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry(ConnPoolByRoute.java:337)
> at
> org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection(ThreadSafeClientConnManager.java:230)
> at
> org.apache.http.impl.client.DefaultClientRequestDirector.execute(DefaultClientRequestDirector.java:427)
> at
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:500)
> at
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:455)
> at
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:421)
> at
> com.limegroup.gnutella.http.DefaultHttpExecutor.performRequest(DefaultHttpExecutor.java:97)
> at
> com.limegroup.gnutella.http.DefaultHttpExecutor.access$000(DefaultHttpExecutor.java:26)
> at
> com.limegroup.gnutella.http.DefaultHttpExecutor$MultiRequestor.run(DefaultHttpExecutor.java:139)
> at
> org.limewire.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1006)
> at
> org.limewire.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:549)
> at java.lang.Thread.run(Thread.java:613)
> ---
> DefaultHttpExecutor$MultiRequestor basically is just a Runnable / Cancellable
> [exposes a cancel() method] that can be cancelled from any thread. cancel
> just calls abort() on the current AbortableHttpRequest, but is called on a
> thread other than the one that's doing the client.execute(request).
> The last one is the most common exception, and seems to happen with some
> regularity. The other two we've only seen once, so may just be a memory quirk
> (we've seen some crazy bugs, including recursive NPEs while constructing an
> NPE.)
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
