In one of the projects I have been involved in, we use yavijava (which is a fork of vijava) library to interact with vCenter which hosts our VMs. vCenter exposes various APIs through their webservice endpoints which are invoked through HTTP(s). The yavijava library has necessary hooks which allows developers to use a HTTP client library of their choice on the client side to handle invocations to the vCenter.
In our integration, we plugged in the Apache HTTP client library, so that the yavijava invocations internally end up using this HTTP library for interaction. Things mostly worked fine and we were able to invoke the vCenter APIs. I say mostly, because every once in a while we kept seeing exceptions like:
InvalidLogin : Cannot complete login due to an incorrect user name or password.
This was puzzling since we were absolutely sure that the user name and password we use to interact with the vCenter was correct. Especially since all of the previous calls were going through fine, before we started seeing these exceptions.
The exception stacktrace didn’t include anything more useful and neither did any other logs. So the only option that I was left with was to go look into the vCenter (server side) event logs to see if I can find something. Luckily, I had access to a setup which had a vSphere client, which I then used to connect to the vCenter. The vSphere client allows you to view the event logs that were generated on the vCenter.
Taking a look at the logs, showed something interesting and useful. Every time, we had run into this “incorrect user name or password” exception on the client side, there was a corresponding event log on the vCenter server side at INFO level which stated “user cannot logon since user is already logged on”. That event log was a good enough hint to give an idea of what might be happening.
Based on that hint, the theory I could form was, somehow for an incoming (login) request, vCenter server side notices something on the request which gives it an impression that the user is already logged in. Given my background with Java EE technologies, the immediate obvious thing that came to mind was that the request was being attached with a “Cookie” which the server side uses to associate requests against a particular session. Since I had access to the client side code which was issuing this login request, I was absolutely sure that the request did not have any explicitly set Cookie header. So that raised the question, who/where the cookie was being associated with the request. The only place that can happen, if it’s not part of the request we issued, is within the HTTP client library. Reading up the documentation of Apache HTTP client library confirmed the theory that the HTTP client was automagically associating a (previously generated) Cookie against the request.
More specifically, the HTTP client library uses pooled connections. When a request is made, one of the pooled connections (if any) gets used. What was happening in this particular case was that, a previous login would pick up connection C1 and the login would succeed. The response returned from vCenter for that login request would include a Cookie set in the response header. The Apache HTTP client library was then keeping track of this Cookie against the connection that was used. Now when a subsequent login request arrived, if the same pooled connection C1 gets used for this request, then the HTTP client library was attaching the Cookie that it kept track against this connection C1, to this new request. As a result, vCenter server side ends up seeing that the incoming login request has a Cookie associated with it, which says that there’s already a logged in session for that request. Hence, that INFO message in the event logs of vCenter. Of course, the error returned isn’t that informative and in fact a bit misleading since it says the username/password is incorrect.
There isn’t much information about this issue anywhere that I could find. The closest I could find was this forum thread https://sourceforge.net/p/vijava/discussion/826592/thread/91550e2a/. It didn’t have a conclusive solution, but it does appear that it’s the same issue that the user there was running into (almost 7 years back!)