Skip to content
This repository has been archived by the owner on Oct 12, 2023. It is now read-only.

WARN okhttp3.OkHttpClient: A connection was leaked #81

Open
JoeBengalen opened this issue Jan 4, 2019 · 5 comments
Open

WARN okhttp3.OkHttpClient: A connection was leaked #81

JoeBengalen opened this issue Jan 4, 2019 · 5 comments

Comments

@JoeBengalen
Copy link

JoeBengalen commented Jan 4, 2019

Hi all,

First off, I'm really glad with the 1.2.0 update. It was a huge improvement in our app performance 馃槂

Having run our app for a while we see lots of random warnings in our logs about a connection leakage.
In a small app based on spring boot with a single rest endpoint calling keyvault I got the same warning.
The warning does not happen for every call to keyvault, it only occurs sometimes (seemingly random).

Note that we encountered this same warning using version 1.1.2 of this library.

WARN okhttp3.OkHttpClient: A connection to https://xxx.vault.azure.net/ was leaked. Did you forget to close a response body?

java.lang.Throwable: response.body().close()
    at okhttp3.internal.platform.Platform.getStackTraceForCloseable(Platform.java:148) ~[okhttp-3.10.0.jar:na]
    at okhttp3.RealCall.captureCallStackTrace(RealCall.java:89) ~[okhttp-3.10.0.jar:na]
    at okhttp3.RealCall.execute(RealCall.java:73) ~[okhttp-3.10.0.jar:na]
    at retrofit2.OkHttpCall.execute(OkHttpCall.java:180) ~[retrofit-2.4.0.jar:na]
    at retrofit2.adapter.rxjava.CallExecuteOnSubscribe.call(CallExecuteOnSubscribe.java:40) ~[adapter-rxjava-2.4.0.jar:na]
    at retrofit2.adapter.rxjava.CallExecuteOnSubscribe.call(CallExecuteOnSubscribe.java:24) ~[adapter-rxjava-2.4.0.jar:na]
    at rx.Observable.unsafeSubscribe(Observable.java:10327) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:48) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:33) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.Observable.subscribe(Observable.java:10423) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.Observable.subscribe(Observable.java:10390) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.observables.BlockingObservable.blockForSingle(BlockingObservable.java:443) ~[rxjava-1.3.8.jar:1.3.8]
    at rx.observables.BlockingObservable.single(BlockingObservable.java:340) ~[rxjava-1.3.8.jar:1.3.8]
    at com.microsoft.azure.keyvault.implementation.KeyVaultClientBaseImpl.getSecret(KeyVaultClientBaseImpl.java:3833) ~[azure-keyvault-1.1.2.jar:1.1.2]
    at com.microsoft.azure.keyvault.implementation.KeyVaultClientCustomImpl.getSecret(KeyVaultClientCustomImpl.java:1148) ~[azure-keyvault-1.1.2.jar:1.1.2]
    at com.jb.azure.keyvault.test.Subject.loadSecret(Subject.java:33) ~[classes/:na]
    at com.jb.azure.keyvault.test.Controller.index(Controller.java:21) ~[classes/:na]

Piece of code calling this library

    private final KeyVaultClient client;

    public String loadSecret(String secretName) throws RuntimeException {
        SecretBundle bundle = client.getSecret(VAULT, secretName);
        if (bundle == null) {
            throw new RuntimeException(String.format("Secret %s not found", secretName));
        }
        LOG.info("Found bundle {}", bundle.id());
        return bundle.value();
    }

Doing an online search I found more people using retrofit/okhttp have seen this.

square/retrofit#1556
square/retrofit#2675
square/okhttp#2311

Main point is that somewhere something was not closed properly.
Since return value of KeyVaultClient.getSecret() is a SecretBundle I am not able to close anything myself.

Please provide a fix for this warning

@JoeBengalen
Copy link
Author

Small app to reproduce the issue. Note that I used version 1.1.2 here since the warning seems to occur sooner/more often compared to 1.2.0

Just run the app and call GET http://localhost:8080/ for a couple minutes.

Application.java

package com.jb.azure.keyvault.test;

import com.microsoft.aad.adal4j.AuthenticationContext;
import com.microsoft.aad.adal4j.AuthenticationResult;
import com.microsoft.aad.adal4j.ClientCredential;
import com.microsoft.azure.keyvault.KeyVaultClient;
import com.microsoft.azure.keyvault.authentication.KeyVaultCredentials;
import com.microsoft.azure.keyvault.models.SecretBundle;
import java.net.MalformedURLException;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.TimeoutException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class Application {
    private static final String SP_USER = "dummy";
    private static final String SP_PASS = "dummy";
    private static final String VAULT = "https://xxx.vault.azure.net/";
    private static final String SECRET = "dummy";

    private static final Logger LOG = LoggerFactory.getLogger(Application.class);

    private final KeyVaultClient client;

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }

    public Application() {
        this.client = new KeyVaultClient(new AzureKeyVaultCredentials(
                SP_USER, SP_PASS, Executors.newSingleThreadExecutor()));
    }

    @GetMapping("/")
    public String index() {
        SecretBundle bundle = client.getSecret(VAULT, SECRET);
        if (bundle == null) {
            throw new RuntimeException(String.format("Secret %s not found", SECRET));
        }
        LOG.info("Found secret");
        return "Found secret " + bundle.id();
    }

    class AzureKeyVaultCredentials extends KeyVaultCredentials {

        private final String clientId;
        private final String clientKey;
        private final ExecutorService executorService;

        public AzureKeyVaultCredentials(String clientId, String clientKey, ExecutorService executorService) {
            this.clientId = clientId;
            this.clientKey = clientKey;
            this.executorService = executorService;
        }

        @Override
        public String doAuthenticate(String authorization, String resource, String scope) {
            try {
                final AuthenticationContext context = new AuthenticationContext(authorization, false, executorService);
                final ClientCredential credential = new ClientCredential(this.clientId, this.clientKey);
                final Future<AuthenticationResult> future = context.acquireToken(resource, credential, null);
                AuthenticationResult result = future.get(60L, TimeUnit.SECONDS);
                return result.getAccessToken();
            } catch (MalformedURLException | TimeoutException | ExecutionException ex) {
                throw new IllegalStateException("Failed to do authentication.", ex);
            } catch (InterruptedException ex) {
                Thread.currentThread().interrupt();
                throw new IllegalStateException("Failed to do authentication.", ex);
            }
        }
    }
}

pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.jb</groupId>
    <artifactId>azure-keyvault-test</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <packaging>jar</packaging>
    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <maven.compiler.source>10</maven.compiler.source>
        <maven.compiler.target>10</maven.compiler.target>
    </properties>
    <dependencies>
        <dependency>
            <groupId>com.microsoft.azure</groupId>
            <artifactId>azure-client-authentication</artifactId>
            <version>1.6.1</version>
        </dependency>
        <dependency>
            <groupId>com.microsoft.azure</groupId>
            <artifactId>azure-keyvault</artifactId>
            <version>1.1.2</version>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
    </dependencies>
    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-dependencies</artifactId>
                <version>2.0.3.RELEASE</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>
    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>
</project>

logs

2019-01-04 12:42:08.592  INFO 12836 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-01-04 12:42:08.596  INFO 12836 --- [           main] com.jb.azure.keyvault.test.Application   : Started Application in 3.529 seconds (JVM running for 4.197)
2019-01-04 12:43:35.239  INFO 12836 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring FrameworkServlet 'dispatcherServlet'
2019-01-04 12:43:35.239  INFO 12836 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization started
2019-01-04 12:43:35.258  INFO 12836 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization completed in 19 ms
2019-01-04 12:43:35.852  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 715f58ca-8d7d-45ce-9cdc-c5f18297e119] Instance discovery was successful
2019-01-04 12:43:36.864  INFO 12836 --- [nio-8080-exec-1] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:43:37.922  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: a01bd89b-f1da-4ff7-909b-f7fdc1b4a34b] Instance discovery was successful
2019-01-04 12:43:38.359  INFO 12836 --- [nio-8080-exec-3] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:43:38.769  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: deafdb42-3d95-4935-8874-63bc499e13f4] Instance discovery was successful
2019-01-04 12:43:39.049  INFO 12836 --- [nio-8080-exec-4] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:43:40.734  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 624c9fb1-279a-434a-9dca-35b1d5785735] Instance discovery was successful
2019-01-04 12:43:41.062  INFO 12836 --- [nio-8080-exec-9] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:45:03.878  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 8e114a3d-2917-409a-911b-90fbe8cc32c5] Instance discovery was successful
2019-01-04 12:45:04.210  INFO 12836 --- [nio-8080-exec-1] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:46:05.354  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 007269a3-47bc-4964-880b-ebebbf405c84] Instance discovery was successful
2019-01-04 12:46:06.482  INFO 12836 --- [nio-8080-exec-4] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:48:17.103  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 534d8759-2e88-4765-b327-4883a6b017e7] Instance discovery was successful
2019-01-04 12:48:18.006  INFO 12836 --- [nio-8080-exec-7] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:49:55.170  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 8dc21df0-f75f-44b3-b9d4-5edd18c52c9f] Instance discovery was successful
2019-01-04 12:49:56.107  INFO 12836 --- [nio-8080-exec-3] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:51:25.963  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 2e3c659a-3667-44c6-81f6-77601faff210] Instance discovery was successful
2019-01-04 12:51:26.537  INFO 12836 --- [nio-8080-exec-9] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:06.065  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 7f8ab4d5-6a62-403a-9201-d8f8f9d235ae] Instance discovery was successful
2019-01-04 12:58:06.805  INFO 12836 --- [nio-8080-exec-1] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:14.653  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 18471a23-54b1-4d74-ac50-9139d48bffa5] Instance discovery was successful
2019-01-04 12:58:14.879  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: fc431a04-67b5-4a4b-8c24-f5961e47be20] Instance discovery was successful
2019-01-04 12:58:15.004  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 123578e6-6a45-443b-9b72-b3294e258d67] Instance discovery was successful
2019-01-04 12:58:15.170  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 20fd471e-6abc-4ac3-b344-8439c6c44515] Instance discovery was successful
2019-01-04 12:58:15.256  INFO 12836 --- [nio-8080-exec-3] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:15.304  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 44104b18-6bac-4607-bdfc-f3694e7d7e51] Instance discovery was successful
2019-01-04 12:58:15.426  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 5d347015-2ccb-4028-a114-2262272c82a3] Instance discovery was successful
2019-01-04 12:58:15.465  INFO 12836 --- [nio-8080-exec-4] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:15.557  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: ce488f7e-fa80-489c-a0b2-a0bc3b2a029e] Instance discovery was successful
2019-01-04 12:58:15.680  INFO 12836 --- [nio-8080-exec-5] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:15.706  INFO 12836 --- [nio-8080-exec-9] com.jb.azure.keyvault.test.Application   : Found secret
2019-01-04 12:58:15.747  INFO 12836 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 846f7f77-4582-4a70-9c0a-556ccc4d439b] Instance discovery was successful
2019-01-04 12:58:15.753  WARN 12836 --- [ ConnectionPool] okhttp3.OkHttpClient                     : A connection to https://xxx.vault.azure.net/ was leaked. Did you forget to close a response body?

java.lang.Throwable: response.body().close()
	at okhttp3.internal.platform.Platform.getStackTraceForCloseable(Platform.java:148) ~[okhttp-3.10.0.jar:na]
	at okhttp3.RealCall.captureCallStackTrace(RealCall.java:89) ~[okhttp-3.10.0.jar:na]
	at okhttp3.RealCall.execute(RealCall.java:73) ~[okhttp-3.10.0.jar:na]
	at retrofit2.OkHttpCall.execute(OkHttpCall.java:180) ~[retrofit-2.4.0.jar:na]
	at retrofit2.adapter.rxjava.CallExecuteOnSubscribe.call(CallExecuteOnSubscribe.java:40) ~[adapter-rxjava-2.4.0.jar:na]
	at retrofit2.adapter.rxjava.CallExecuteOnSubscribe.call(CallExecuteOnSubscribe.java:24) ~[adapter-rxjava-2.4.0.jar:na]
	at rx.Observable.unsafeSubscribe(Observable.java:10327) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:48) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeMap.call(OnSubscribeMap.java:33) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.Observable.subscribe(Observable.java:10423) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.Observable.subscribe(Observable.java:10390) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.observables.BlockingObservable.blockForSingle(BlockingObservable.java:443) ~[rxjava-1.3.8.jar:1.3.8]
	at rx.observables.BlockingObservable.single(BlockingObservable.java:340) ~[rxjava-1.3.8.jar:1.3.8]
	at com.microsoft.azure.keyvault.implementation.KeyVaultClientBaseImpl.getSecret(KeyVaultClientBaseImpl.java:3833) ~[azure-keyvault-1.1.2.jar:1.1.2]
	at com.microsoft.azure.keyvault.implementation.KeyVaultClientCustomImpl.getSecret(KeyVaultClientCustomImpl.java:1148) ~[azure-keyvault-1.1.2.jar:1.1.2]
>       at com.jb.azure.keyvault.test.Application.index(Application.java:46) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:209) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851) ~[spring-webmvc-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-embed-websocket-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.7.RELEASE.jar:5.0.7.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-8.5.31.jar:8.5.31]
	at java.base/java.lang.Thread.run(Thread.java:844) [na:na]

@piotr-napadlek
Copy link

Observing the same behaviour, in our case we get a new thread allocated for any getSecret() operation:

2019-03-11 11:28:29.875  INFO 20 --- [pool-1-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: c332ec92-ef91-4f4e-a29f-9e0fef44b885] Instance discovery was successful
2019-03-11 11:28:30.322  INFO 20 --- [pool-2-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 33ce1768-42b9-45cb-b761-5d5ad764f2a8] Instance discovery was successful
2019-03-11 11:28:30.720  INFO 20 --- [pool-3-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: eb7eee0c-ac3f-492f-ad7b-25b951b7b053] Instance discovery was successful
2019-03-11 11:28:30.859  INFO 20 --- [pool-4-thread-1] c.m.aad.adal4j.AuthenticationAuthority   : [Correlation ID: 167df797-a93c-452e-92b3-0a1c913cd3c7] Instance discovery was successful
...
2019-03-11 11:33:29.739  WARN 20 --- [ ConnectionPool] okhttp3.OkHttpClient                     : A connection to https://xxx-kv.vault.azure.net/ 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);

@FireDrunk
Copy link

keyVaultClient.httpClient().connectionPool().evictAll();

Seems to fix the issue.

@JoeBengalen
Copy link
Author

@FireDrunk Where/when do you call this evictAll? After each call to keyvault (client.getSecret())?

@FireDrunk
Copy link

I've just added it after the end of my 'get all relevant info from keyvault' function, I don't know what the minimal amount of eviction's would be.
I've done multiple queries, and haven't seen the warning any more.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants