GCP Cloud Spanner gives com.google.cloud.spanner.SessionPool$LeakedSessionException for every read and write operation through Java application

Question

I have a SpringBoot Java application which connects to Cloud Spanner Database. There are no issues w.r.t connection and also able to read and write data into the tables but when checking warn/trace level logs in Dynatrace I can see there is one exception being thrown for every call to Spanner Database. Are there any configurations for Spanner which I'm missing or is it something I should worry about and how to fix this if it is an issue? Please help.

Here is the spanner dependency being used in my code -

    <dependency>
      <groupId>com.google.cloud</groupId>
      <artifactId>google-cloud-spanner</artifactId>
      <version>6.10.1</version>
      <scope>compile</scope>
    </dependency>

Also checked the spanner source code - https://github.com/googleapis/java-spanner/blob/main/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

Below are the exception details -

(I've intentionally hidden some classes - client confidentiality stuff you know -_-)

Exception:
com.google.cloud.spanner.SessionPool$LeakedSessionException

Message:
Session was checked out from the pool at 2022-07-13T17:50:07.372Z

Stacktrace:
com.google.cloud.spanner.SessionPool$PooledSessionFuture.markCheckedOut(SessionPool.java:1093)
com.google.cloud.spanner.SessionPool$PooledSessionFuture.access$
com.google.cloud.spanner.SessionPool.checkoutSession(SessionPool.java:2037)
com.google.cloud.spanner.SessionPool.getSession(SessionPool.java:2018)
com.google.cloud.spanner.DatabaseClientImpl.getSession(DatabaseClientImpl.java:53)
com.google.cloud.spanner.DatabaseClientImpl.singleUse(DatabaseClientImpl.java:101)
com.google.cloud.spring.data.spanner.core.SpannerTemplate$$Lambda$.get
com.google.cloud.spring.data.spanner.core.SpannerTemplate.doWithOrWithoutTransactionContext(SpannerTemplate.java:643)
com.google.cloud.spring.data.spanner.core.SpannerTemplate.getReadContext(SpannerTemplate.java:126)
com.google.cloud.spring.data.spanner.core.SpannerTemplate.performQuery(SpannerTemplate.java:485)
com.google.cloud.spring.data.spanner.core.SpannerTemplate.executeQuery(SpannerTemplate.java:448)
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.getResponse(<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.java:36)
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>$$FastClassBySpringCGLIB$$c883d7ab.invoke(<generated>)
org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>$$EnhancerBySpringCGLIB$$.getResponse
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.processGetRequest(<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.java:50)
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>$$FastClassBySpringCGLIB$$cd4920ff.invoke(<generated>)
org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>$$EnhancerBySpringCGLIB$$.processGetRequest
com.<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.<INTENTIONALLY HIDDEN PROJECT SPECIFIC METHOD>(<INTENTIONALLY HIDDEN PROJECT SPECIFIC CLASS>.java:34)
jdk.internal.reflect.NativeMethodAccessorImpl.invoke0
jdk.internal.reflect.NativeMethodAccessorImpl.invoke
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke
java.lang.reflect.Method.invoke
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)

Answer 1

I'm not familiar with Dynatrace, so I'm not 100% sure what it does in this case, but my impression is that this is a false positive in the reporting of Dynatrace.

The Cloud Spanner client library internally uses a session pool. This session pool will mark each session when it is checked out with the call stack of the thread that checks out the session. It does so to make it easier to find where a session leak is coming from if a session leak occurs. This process works like this:

1. Create a LeakedSessionException to catch the call stack of the current thread here: https://github.com/googleapis/java-spanner/blob/1822a138b254c8645dee629a5a055ba3dfe822a9/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L1104
2. This method is called when a session is checked out: https://github.com/googleapis/java-spanner/blob/1822a138b254c8645dee629a5a055ba3dfe822a9/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L2135
3. The LeakedSessionException is cleared from the session when it is checked back into the pool (this happens when the session is closed): https://github.com/googleapis/java-spanner/blob/1822a138b254c8645dee629a5a055ba3dfe822a9/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L1282

So as you can see from the above the exception will under normal circumstances only be created, but not thrown or logged. If you do happen to have a session leak, then the exception will be used to throw or log an error when the session pool is closed: https://github.com/googleapis/java-spanner/blob/1822a138b254c8645dee629a5a055ba3dfe822a9/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java#L2275

Is Dynatrace logging this exception when you close your application? Or is it logging it during normal operation? If the latter is the case, it is certainly a false positive from Dynatrace.