Friday, January 21, 2022

[FIXED] Running out of JDBC connections when loading entity in StreamingResponseBody

January 21, 2022 hibernate, jdbc, spring, spring-boot

Issue

I am currently working on a streaming service which I want to use to play audio files on the client in a more efficient manner. In order to do so I have an endpoint which returns a StreamingRepsonseBody and only the requested bytes of an audio file.

However, After streaming an audio file however, I run into the problem of getting a CannotGetJdbcConnectionException for any request I make towards the server (find the full stack trace below).

It seems that the database connection is never getting closed. The exception gets (usually) thrown after 10 requests (I think this is also the limit of open connections).

I was able to "solve" this problem by just not making a call to the database but this means that the client has to send me the information which I'd normally fetch from the database

The Working Endpoint

If I get the bucketName and bucketFilename via @RequestParam, I do not need to fetch the TrackEntity from the database and the streaming endpoint works as expected:

@RequestMapping(
        value = "/tracks/{trackId}/play",
        method = RequestMethod.GET,
        produces = MediaType.APPLICATION_OCTET_STREAM_VALUE
)
public StreamingResponseBody playTrack(
        @PathVariable("trackId") Long trackId,
        @RequestHeader("Range") String range,
        @RequestParam("bucketName") String bucketName,
        @RequestParam("bucketFilename") String bucketFilename
) {
    String[] rangeValues = range.split("=")[1].split("-");
    int rangeStart = Integer.parseInt(rangeValues[0]);
    int rangeEnd = Integer.parseInt(rangeValues[1]);
    int rangeSize = rangeEnd - rangeStart;

    InputStreamResource inputStreamResource = this.trackService
            .readChunk(bucketName, bucketFilename, rangeStart);

    return outputStream -> {
        try (InputStream inputStream = inputStreamResource.getInputStream()) {
            StreamUtils.copyRange(inputStream, outputStream, 0, rangeSize);
        }
    };
}

The Broken Endpoint

This is how it should be. Using the trackService I want to load the TrackEntity from the database. However, this is where the exception comes from.

@RequestMapping(
        value = "/tracks/{trackId}/play",
        method = RequestMethod.GET,
        produces = MediaType.APPLICATION_OCTET_STREAM_VALUE
)
public StreamingResponseBody playTrack(
        @PathVariable("trackId") Long trackId,
        @RequestHeader("Range") String range
) {
    String[] rangeValues = range.split("=")[1].split("-");
    // Fetch TrackEntity from the database
    TrackEntity track = this.trackService.getTrack(trackId);
    String bucketName = track.getBucketName();
    String bucketFilename = track.getBucketFilename();

    int rangeStart = Integer.parseInt(rangeValues[0]);
    int rangeEnd = Integer.parseInt(rangeValues[1]);
    int rangeSize = rangeEnd - rangeStart;

    InputStreamResource inputStreamResource = this.trackService
            .readChunk(bucketName, bucketFilename, rangeStart);

    return outputStream -> {

        try (InputStream inputStream = inputStreamResource.getInputStream()) {
            StreamUtils.copyRange(inputStream, outputStream, 0, rangeSize);
        }
        System.out.println(String.format("Fetched %.4f MB", (rangeSize / Math.pow(1024.0, 2))));
    };
}

This is the implementation of getTrack(). Nothing exciting here.

public TrackEntity getTrack(Long trackId) {
    return this.trackRepository.findById(trackId)
            .orElseThrow(ResourceNotFoundException::new);
}

Full Stack Trace

This is the complete stack trace of the exception thrown.

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:612) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:669) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:700) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:712) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:790) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.security.oauth2.provider.token.store.JdbcTokenStore.readAccessToken(JdbcTokenStore.java:160) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.security.oauth2.provider.token.DefaultTokenServices.loadAuthentication(DefaultTokenServices.java:229) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.security.oauth2.provider.token.DefaultTokenServices$$FastClassBySpringCGLIB$$5a1f25c.invoke(<generated>) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:685) ~[spring-aop-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.security.oauth2.provider.token.DefaultTokenServices$$EnhancerBySpringCGLIB$$76cd39c0.loadAuthentication(<generated>) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationManager.authenticate(OAuth2AuthenticationManager.java:83) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationProcessingFilter.doFilter(OAuth2AuthenticationProcessingFilter.java:150) ~[spring-security-oauth2-2.3.2.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:157) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178) ~[spring-security-web-5.2.1.RELEASE.jar:5.2.1.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at io.ear.spring.config.SimpleCORSFilter.doFilter(SimpleCORSFilter.java:36) ~[classes/:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1591) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.29.jar:9.0.29]
    at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:697) ~[HikariCP-3.4.1.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196) ~[HikariCP-3.4.1.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161) ~[HikariCP-3.4.1.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:na]
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    ... 64 common frames omitted

Stack Trace to "Apparent connection leak detected"

Thanks to M. Deinum I was able to find the leak in the first place by setting in my application.properties the following:

logging.level.org.springframework.security=DEBUG
spring.datasource.hikari.leak-detection-threshold=15000

Which led me to the exception:

java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.9.Final.jar:5.4.9.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.9.Final.jar:5.4.9.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104) ~[hibernate-core-5.4.9.Final.jar:5.4.9.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134) ~[hibernate-core-5.4.9.Final.jar:5.4.9.Final]
    at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:462) ~[hibernate-core-5.4.9.Final.jar:5.4.9.Final]
    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.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282) ~[spring-core-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:266) ~[spring-core-5.2.2.RELEASE.jar:5.2.2.RELEASE]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle.doGetConnection(HibernateJpaDialect.java:430) ~[spring-orm-5.2.2.RELEASE.jar:5.2.2.RELEASE]
   ...

Solution

First don't use the SimpleTaskExecutor that will lead to issues later on (it will create Thread objects for each incoming request and might not clean them up properly.
Your code might have a resource leak by not closing the InputStream and/or by going into a continuous loop.
You are using JPA and by default the spring.jpa.open-in-view property is enabled (you will get a warning on startup if you didn't set it explicitly). You might want to switch this to false to only open a session when needed.

To fix 1, just remove your bean definition and Spring Boot will configure a proper TaskExecutor for you (out-of-the-box).

For number 2 rewrite the code in your controller to prevent resource leaks.

@GetMapping(
        value = "/tracks/{trackId}/play",
        produces = MediaType.APPLICATION_OCTET_STREAM_VALUE
)
public StreamingResponseBody playTrack(
        @PathVariable("trackId") Long trackId,
        @RequestHeader("Range") String range
) {

    String[] rangeValues = range.split("=")[1].split("-");

    int rangeStart = Integer.parseInt(rangeValues[0]);
    int rangeEnd = Integer.parseInt(rangeValues[1]);

    return outputStream -> {
        InputStreamResource inputStreamResource = this.trackService.playTrack(trackId);
        try (InputStream inputStream = inputStreamResource.getInputStream()) {
          StreamUtils.copyRange(inputStream, outputStream, rangeStart, rangeEnd);        
        }       
    };
}

This code will close the InputStream and the StreamUtils.copyRange will never go into an infinite loop (and it cleans up your code).

Number 3 is quite easy to fix add the following to your application.properties.

spring.jpa.open-in-view=false

This might, however, have implications for other parts of your application not working properly anymore. Especially if you have a view and rely on the open session in view pattern to automatically retrieve not yet retrieved data (i.e. lazy relations in your entities).

Answered By - M. Deinum
Answer Checked By - Timothy Miller (JavaFixing Admin)

This Answer collected from stackoverflow and tested by JavaFixing community admins, is licensed under cc by-sa 2.5 , cc by-sa 3.0 and cc by-sa 4.0