A connection to <address> was leaked. Did you forget to close a response body?

[traviswinter]

I understand this issue comes up from time to time on the issues but I'm not actually able to find the cause of the issue I'm encountering.

Using the Fabric8 Kubernetes Client (https://github.com/fabric8io/kubernetes-client) which uses Okhttp to make calls to a Restful API (Kubernetes to be specific). They raised a similar issue for their Watch Manager (#4374) but I'm still seeing issues when I make direct calls to their client.

I've tracked the code to the following code in the Kubernetes Client:

protected <T> T handleResponse(OkHttpClient client, Request.Builder requestBuilder, Class<T> type, Map<String, String> parameters) throws ExecutionException, InterruptedException, KubernetesClientException, IOException { VersionUsageUtils.log(this.resourceT, this.apiVersion); Request request = requestBuilder.build(); Response response = client.newCall(request).execute(); try (ResponseBody body = response.body()) { assertResponseCode(request, response); if (type != null) { return Serialization.unmarshal(body.byteStream(), type, parameters); } else { return null; } } catch (Exception e) { if (e instanceof KubernetesClientException) { throw e; } throw requestException(request, e); } finally { if(response != null && response.body() != null) { response.body().close(); } } }

The scenario is multiple calls to the same client in quick succession (10-50 at once) and sporadically I see the error:

2018-11-19 10:57:46,735 [OkHttp ConnectionPool] [WARN ] okhttp3.OkHttpClient - A connection to https://<host>:6443/ was leaked. Did you forget to close a response body? To see where this was allocated, set the OkHttpClient logger level to FINE: Logger.getLogger(OkHttpClient.class.getName()).setLevel(Level.FINE);

When I set it to FINE I see it complaining about "client.newCall(request).execute();" in "handleResponse" above.

When I create a new client for each request, I still see the issue but it is dramatically reduced (from 10 messages per 100 calls to 1 message per 100 calls). This leads me to believe there may be some sort of race condition, or maybe the exception handling in that case is incorrectly reporting the error? I ran my code for the entire weekend in YourKit and see thousands of messages but funnily enough when I GC, I didn't see a large growth in any okhttp objects (StreamAllocation objects increased by 160 objects).

I attempted to create a test, but using the MockWebServer does not replicate the issue and I'm unaware of a public server you may want to use in your bug testing. I even tried to replicate it using the Kubernetes mock server and couldn't replicate it.

I know that its odd to come here for this issues, but the code they're using looks to be solid and the exception seems to indicate an issue with the "client.newCall(request).execute();" call.

Any help would be appreciated!

[swankjesse]

I believe we fixed this with OkHttp 3.12.
#4258

Confirm?

[traviswinter]

Sorry, I forgot to mention that I was following that fix and had built a snapshot of master to work with the client.

You can see my findings here: fabric8io/kubernetes-client#1090

The gist was that the fix was for a Watcher that continually checks event streams, but I was able to replicate just by making calls in quick succession. I'm not sure how familiar you are with Kubernetes, but the odd thing was that earlier versions of the Kubernetes Rest API seem more susceptible to the issue. Newer versions (1.9+) rarely have the issue - making me think this is a race condition and their API either sped up (more likely) or slowed down to avoid it.

The issue is very inconsistent - I tried debugging through a couple hundred calls and there doesn't seem to be any real indication of a leak until it finds the null referent in the StreamAllocation reference. It's possible I missed something but it seemed like the referent was just garbage collected when response body was closed, but the annotations for the connection still kept the weak reference for that small period of time.

Of note was the fact that I did see the connection cleanup happening around the same time these leaks were found, but that could be a red herring.

Thanks for getting back to me, and here if you have any other questions :)

[swankjesse]

Interesting! Any guess as to whether the leaked connection was successfully upgraded?

A standalone test that reproduces the leak would be very valuable, even if it takes many minutes to trigger. Doesn't have to be JUnit if ya wanna spawn a bunch of threads! Otherwise we’ll try to put that together.

[traviswinter]

Sorry, not super familiar with the code. What do you mean when you say successfully upgraded?

Also, I referenced the wrong issue before - fabric8io/kubernetes-client#1228 is the one where I was keeping track of issues.

I have a test in fabric8io/kubernetes-client#1228 but it utilizes the Fabric8 client. Its basically, create a client, make a request in a loop, then watch the log. I'll see if I can create a straight okhttp test that hits the same issue today and post it.

Thanks for the quick responses!

[swankjesse]

Great. MockWebServer is your friend, especially with a custom Dispatcher.

“Upgrade” is the HTTP term when a client and server successfully negotiatea web socket.

[traviswinter]

It looks like I can't replicate it using the MockWebServer and I tried making calls directly to an AKS cluster I created without encountering the exception. Going to keep trying, maybe specifically with Fabric8's client and see how it goes.

As to the upgrade, I believe so - as I was debugging, every single call executed and seemed to do so correctly, but then after a period (when cleanup occurred) I would see the issue.

One question - if body.byteStream() is called, will that InputStream be closed on response.body().close()?

[traviswinter]

It looks like the body.byteStream() is the problem - my assumption that it closed on body.close() seems to be incorrect, and modifying the code to keep track of open streams would be unweildly. Maybe a javadoc comment indicating the requirement to close it would make sense.

Regardless, looks like an issue in the Fabric8 Kubernetes Client so closing here. Thanks for your help @swankjesse !

[swankjesse]

Hang on, @traviswinter. When you call ResponseBody.close() that also closes the various streams you get from it.

The heavyweight thing behind-the-scenes that really needs closing is the Socket. There’s a few lightweight abstractions over it: the BufferedSource returned from source(), the InputStream returned from byteStream(), and the Reader returned from charStream(). If you close any of these or the ResponseBody it’ll release the Socket and prevent the leaked connection warning.

[traviswinter]

Ah, so maybe there is an issue in the okhttp code after all.

The moment I changed:

return Serialization.unmarshal(body.byteStream(), type, parameters);

to:

try (InputStream bodyInputStream = body.byteStream()) { return Serialization.unmarshal(bodyInputStream, type, parameters); }

the issue went away. Perhaps that body.byteStream() input stream isn't being closed properly on response body close. Right now, that entire piece of code is in a try with resources associated with the response body, so it was definitely being closed before.

[JakeWharton]

In the former example, an exception during read will leak the connection.

…

On Fri, Nov 23, 2018, 12:30 PM Travis Winter ***@***.*** wrote: Ah, so maybe there is an issue in the okhttp code after all. The moment I changed: return Serialization.unmarshal(body.byteStream(), type, parameters); to: try (InputStream bodyInputStream = body.byteStream()) { return Serialization.unmarshal(bodyInputStream, type, parameters); } the issue went away. Perhaps that body.byteStream() input stream isn't being closed properly on response body close. Right now, that entire piece of code is in a try with resources associated with the response body, so it was definitely being closed before. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#4399 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAEEEQXkwjwvVr-7a96PZMVTBZg9wgHbks5uyDCegaJpZM4YpaYA> .

[dave-r12]

@traviswinter I've been following along here and it'd be great to nail down exactly the issue you're seeing. I've put together a standalone OkHttp test case but I'm unable to replicate it. Could you have a look and see if I'm missing something? The only other idea I have is that maybe there is an Interceptor in the mix that is mucking around with the Response and/or ResponseBody.

https://gist.github.com/dave-r12/ee867090f295e0c67ca318d9339c601f

@JakeWharton the former is enclosed with try (ResponseBody body = response.body()), so I think it should close the response body with an exception. Here is the original code formatted:

  protected <T> T handleResponse(OkHttpClient client, Request.Builder requestBuilder, Class<T> type,
      Map<String, String> parameters) 
      throws ExecutionException, InterruptedException, KubernetesClientException, IOException {
    VersionUsageUtils.log(this.resourceT, this.apiVersion);
    Request request = requestBuilder.build();
    Response response = client.newCall(request).execute();
    try (ResponseBody body = response.body()) {
      assertResponseCode(request, response);
      if (type != null) {
        return Serialization.unmarshal(body.byteStream(), type, parameters);
      } else {
        return null;
      }
    } catch (Exception e) {
      if (e instanceof KubernetesClientException) {
        throw e;
      }
      throw requestException(request, e);
    } finally {
      if (response != null && response.body() != null) {
        response.body().close();
      }
    }
  }

[traviswinter]

Not at a computer right now, but the interesting thing is that no exceptions are thrown. In the Fabric8 test class I made, the only exceptions thrown seem to be the resource leaks.

As for reproducing it, I was only able to do it against Kubernetes 1.8 clusters and below. I tried it against 6-8 different clusters and each time I hit a Kubernetes v1.9+ API it worked fine (no exceptions). In each case they used the same client-cert authentication (not token). It was also specific endpoints (apps/Deployment, but not v1/nodes for example).

All the pieces together seem to indicate situations where there are many/constant calls to the API the InputStream is not closed in all cases. It's possible an exception is swallowed somewhere but there were no indications in the log.

I'll try to replicate with your code when I get log in tonight :)