Adding stronger pooling config for client #42
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
DiegoPino
approved these changes
Aug 15, 2017
Codecov Report
@@ Coverage Diff @@
## master #42 +/- ##
============================================
- Coverage 92.15% 91.74% -0.42%
Complexity 58 58
============================================
Files 8 8
Lines 663 666 +3
Branches 3 3
============================================
Hits 611 611
- Misses 49 52 +3
Partials 3 3
Continue to review full report at Codecov.
|
|
@ajs6f I'm performing a clean Things like these are basically impossible to test for, so I'll just do what I can. |
|
Trying this after fcrepo4-labs/fcrepo-api-x#127 has landed makes it far easier to reproduce. Unfortunately, setting the connection pool to shared doesn't seem to have any effect. From what I can tell, the issue only happens on a fresh install. If I get the error, I can uninstall and re-install the feature, leaving the alpaca features in place, and everything is fine. So I'm wondering if the timing issue is on the availability of our custom client? I'm going to add a sleep into our script for installing the features, which we all know won't last forever, but might plug the hole for the time being. |
|
|
It could be a timing issue. It's hard to reason about OSGi's dynamism sometimes. I'm wondering if some internal components are holding on to the old client, and some the new? Let me look into that |
|
@birkland ++ That's just the sort of thing I was wondering about. |
|
Yeah. If that's the case, then I think the easiest solution would have blueprint reload bundles whenever the new service binds. I know how to specify that in Declarative Services (i.e. static vs dynamic), but not Blueprint. That might be worth trying right off the bat. |
|
@ajs6f We are installing the feature for our custom client before installing any api-x feature, so it should be available, but you never know with Karaf sometimes. @birkland And the sleep doesn't really seem to be doing anything, but cycling the feature appears to work 100% of the time. That seems to support your theory. |
|
Hrm... before I get too down on the sleep idea, I'm going to give it something crazy like a full 60 seconds and see what that does. |
|
@dannylamb even 90 seconds would be not too crazy 😄 |
|
Speaking as a parent of young kids, you can never have too much sleep. |
|
@dannylamb Can you set log level to DEBUG (for org.fcrepo.apix), and attach or send a copy of the Karaf logs? There's a proxy for HttpClient that is supposed to deal with the dynamism. I just want to make sure I understand what it's doing, in the context of when this error occurs. |
|
@birkland Getting this on repeat: |
|
That's bizarre. Where are the logging messages from HttpClientFetcher? I was hoping to see the logging messages from |
|
@dannylamb @birkland That's on repeat-- is that what shows up the first time you try to load the API-X features? |
|
@ajs6f @DiegoPino Even a 90 second sleep didn't do it :( Guess we're not Batman here: |
|
"Doctor Death" should be the code name for the CLAW 1.0 release. |
|
I hope it's there. I don't much like going in the direction of "am I running the code I think I'm running?", followed by "Is instruction actually being executed when I think it is?", and "What is the thing in the black box actually doing?" |
|
@birkland If you don't like those things I have no idea why you got into the line of work you did. :) |
|
@dannylamb does it matter what you reinstall (I mean if you don't touch API-X, and "reinstall" Alpaca, does it work also, or do you need to redeploy api-X to get it running?) or do you bootstrap/reload/cleaning all related bundles including API-X and Alpaca... again, in between meetings so just a quick question probably without any effect at all. I mean, if its a matter of just Alpaca with a reload strategy for changed configs in blueprint, that could be easily forced during install.. as a workaround.. eh-- bad idea.. |
|
@birkland, It's there, but the log rollover is making it hard for me to line things up. I'm clearing the data directory and starting over so it's a bit cleaner. Just a moment. |
|
@DiegoPino That's a good question re: which one really matters to reload |
|
Got some good and bad news. Good news is there are logging statements pertaining to the HttpClientFetcher, but unfortunately I can't actually find any entries from the line you posted above.
What I do have is this: Later followed by: and And then finally the error message I posted above. So not much to go on other than we know the service is getting published and having its priority set (at least that's what I think is going on). |
|
But at some point, somehow, API-X must be picking up the CLAW client or it would never be able to act against the Syn-guarded LDP API, right? |
|
@ajs6f When it works successfully, yes. But when we're experiencing this, I guess it never gets to that point. I'm testing by wiping the data directory and starting over, so it doesn't have to bootstrap the resources (they're already in Fedora). @birkland Let me try poking it by loading a service and seeing what happens. |
|
Let me wrap something up, and see if I can at least observe it logging what it should. There's an IT that uses an OSGi-published service, so it's the same pattern (though without the errors) |
|
@ajs6f question: could https://github.com/fcrepo4-labs/fcrepo-api-x/blob/9fe9028bc82fd5e7a6f3f0c1393a78688d0af6a8/fcrepo-api-x-jena/src/main/java/org/fcrepo/apix/jena/impl/JenaServiceRegistry.java called here https://github.com/fcrepo4-labs/fcrepo-api-x/blob/9fe9028bc82fd5e7a6f3f0c1393a78688d0af6a8/fcrepo-api-x-jena/src/main/resources/OSGI-INF/blueprint/blueprint.xml be taken out of the "bootstrap" process, as a separate state (in case you have all the LDP containers/RDF resource needed to start in place?) or even something that runs way before the actual services that make use of the services is initialized? Also, I see some init.await around (before each resource creation etc). defined here used at fcrepo4-labs/fcrepo-api-x@9fe9028#diff-04b47325da2011264c3e37a2c41bd1eaR101 just before we pass our client.. I really don´t know enough java (or anything) but that seems a complex "awaiting" logic, with some thread pool thing , could that be possibly associated with this? multi threaded stuff could have that effect. |
|
@DiegoPino It's complex because of limitations of the Blueprint lifecycle. We eventually gave up on relying on the framework to start things in order; With Blueprint, it's "everything in the bundle starts" or "everything waits", not "any service inside the bundle that is satisfied can start".. which is what Declarative services (and just about everything else, I bet) does. The twist: There's no way a priori to know that we need to wait for a specific HttpClient before starting; so it can and does start with the one we don't want, then swaps implementations once it's available. |
|
@birkland makes sense, agree. It's just me getting a bit late into the game (and preparing my mind for next week´s install sprint) so probably some of my questions can be pretty naive. Sorry for that. I do like (hat off) what you have done with API-X it is really huge =) |
|
@DiegoPino No worries. It's the result of a lot of trial, error, and pain! @dannylamb So logging works for me. If logging is globally set to DEBUG, you should see something like the below: 2017-08-16 16:27:31,931 | INFO | pool-2-thread-1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Set default client org.apache.http.impl.client.InternalHttpClient@e24a76b 2017-08-16 16:27:31,931 | INFO | pool-2-thread-1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Got new HttpClient service. 2017-08-16 16:27:31,932 | INFO | pool-2-thread-1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Using new HttpClient service org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:31,936 | DEBUG | pool-2-thread-1 | BlueprintCamelContext | 38 - org.apache.camel.camel-blueprint - 2.18.4 | Service org.osgi.framework.ServiceEvent[source=[org.fcrepo.apix.registry.HttpClientFetcher]] changed to 1 2017-08-16 16:27:31,938 | DEBUG | pool-2-thread-1 | fcrepo-api-x-registry | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | ServiceEvent REGISTERED - [org.fcrepo.apix.registry.HttpClientFetcher] - fcrepo-api-x-registry 2017-08-16 16:27:32,029 | DEBUG | pool-29-thread-1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,030 | DEBUG | pool-29-thread-2 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,031 | DEBUG | pool-29-thread-3 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,529 | DEBUG | pool-29-thread-2 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,529 | DEBUG | pool-29-thread-3 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,572 | DEBUG | pool-29-thread-1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:32,925 | DEBUG | pool-29-thread-4 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:33,112 | DEBUG | pool-29-thread-6 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:33,409 | DEBUG | pool-29-thread-5 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:33,516 | DEBUG | pool-29-thread-5 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,213 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,249 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,287 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,320 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,353 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,386 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,423 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,471 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,498 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,521 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:34,666 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,060 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,083 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,106 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,128 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,151 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,174 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,198 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,220 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,259 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,295 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,327 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,347 | DEBUG | ion(1)-127.0.0.1 | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,462 | DEBUG | dalityIT/objects | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,474 | DEBUG | dalityIT/objects | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,491 | DEBUG | dalityIT/objects | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,679 | DEBUG | ceptingServiceIT | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,686 | DEBUG | ceptingServiceIT | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,700 | DEBUG | ceptingServiceIT | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,747 | DEBUG | ceptingServiceIT | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:35,780 | DEBUG | ceptingServiceIT | HttpClientFetcher | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | Executing with client org.apache.http.impl.client.InternalHttpClient@1ceb3015 2017-08-16 16:27:36,090 | DEBUG | FelixShutdown | BlueprintCamelContext | 38 - org.apache.camel.camel-blueprint - 2.18.4 | Service org.osgi.framework.ServiceEvent[source=[org.fcrepo.apix.registry.HttpClientFetcher]] changed to 4 2017-08-16 16:27:36,090 | DEBUG | FelixShutdown | fcrepo-api-x-registry | 17 - fcrepo-api-x-registry - 0.3.0.SNAPSHOT | ServiceEvent UNREGISTERING - [org.fcrepo.apix.registry.HttpClientFetcher] - fcrepo-api-x-registry |
|
@birkland Ok, I did a |
|
@dannylamb Great! So now we want to see the debug logs from the beginning (i.e. when It starts making its first requests, gets the new HttpClient from OSGi, etc) |
|
@birkland After re-installing the feature and it working successfully, I'm now getting this: Which seems the same save I'm going to try recreating the issue and see if it ever swaps clients. |
|
@birkland Gosh... my firefox caches too agressively. I never see your new posts. I'm on it, give me a sec. |
|
@birkland Looks like Api-X is getting our custom client. @ajs6f I'm going to try setting it to use a shared connection manager and see what happens. |
|
@dannylamb Would it be possible to e-mail me (or otherwise make accessible) the whole log? I'm interested in seeing if any requests were made with the old client before the new, and other timing issues, etc. |
|
@ajs6f I've cycled the features several times now and cannot reproduce the error with a shared connection manager.
|
|
@dannylamb Yaaaay! So does that mean that something, somewhere is attempting to close the httpclient itself? I don't have a good mental model of what's going on |
|
@birkland Yes that seems to be the case, and I'm not sure what the long-term ramifications of sharing the connection manager are going to be. But at least it will be working for the time being. |
|
On the road, will add a commit tonight or tomorrow!
… On Aug 17, 2017, at 11:56 AM, dannylamb ***@***.***> wrote:
@birkland Yes that seems to be the case, and I'm not sure what the long-term ramifications of sharing the connection manager are going to be. But at least it will be working for the time being.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.
|
DiegoPino
approved these changes
Aug 23, 2017
dannylamb
approved these changes
Aug 23, 2017
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
689: (Islandora/documentation#689)
fcrepo4-labs/fcrepo-api-x#126
What does this Pull Request do?
Adds config to CLAW's API-X HTTP client to prevent connection pool interactions.
What's new?
Add an independent connection pool and keep it open
No.
No.
No.
No.
How should this be tested?
GOOD QUESTION! @dannylamb -- thoughts?
A description of what steps someone could take to:
Interested parties
@dannylamb @DiegoPino @birkland