Random "Specified statement was not created by this connection"

[ambition-consulting]

Hi, using the official jaybird 5.0.10.java11.jar I am getting

org.springframework.transaction.TransactionSystemException: JDBC commit failed
	at org.springframework.jdbc.datasource.DataSourceTransactionManager.translateException(DataSourceTransactionManager.java:439)
	at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:340)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:698)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:416)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:728)
	at foo
	at foo
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:360)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:196)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
	at io.micrometer.core.aop.TimedAspect.processWithTimer(TimedAspect.java:262)
	at io.micrometer.core.aop.TimedAspect.perform(TimedAspect.java:227)
	at io.micrometer.core.aop.TimedAspect.ajc$inlineAccessMethod$io_micrometer_core_aop_TimedAspect$io_micrometer_core_aop_TimedAspect$perform(TimedAspect.java:1)
	at io.micrometer.core.aop.TimedAspect.timedMethod(TimedAspect.java:218)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:649)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:631)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:71)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:728)
	at foo
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124)
	at io.micrometer.observation.Observation.observe(Observation.java:498)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124)
	at org.springframework.scheduling.config.Task$OutcomeTrackingRunnable.run(Task.java:85)
	at io.opentelemetry.javaagent.instrumentation.spring.scheduling.v3_1.SpringSchedulingRunnableWrapper.run(SpringSchedulingRunnableWrapper.java:37)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:96)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.sql.SQLException: Connection has already been closed.
	at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:121)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:107)
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:93)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:107)
	at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
	at jdk.proxy3/jdk.proxy3.$Proxy569.commit(Unknown Source)
	at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:337)
	... 45 more

together with a previous

Specified statement was not created by this connection: org.firebirdsql.jdbc.FBPreparedStatement@28103

by org.firebirdsql.jdbc.FBConnection.

[mrotteveel]

I already fixed a potential cause while investigating the previous issue you reported (in commit 7d8d610). I'll see if there are other cases where the connection might not be aware of the existence of the statement even though it's initialized. Possibly, it is a case of the statement close getting notified twice, or getting notified after the statement was already removed from the list of active statements of the connection.

I'll probably also downgrade this logging from a warning to debug.

[ambition-consulting]

Any plans when to release this? Also, I keep seeing closed connections for no reason, like this one:

Can't set trace ID or customer ID in FireBird context: 
org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [select rdb$set_context(?, ?, ?) from rdb$database]; SQL state [null]; error code [0]; Connection has already been closed.
	at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1557)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:677)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:723)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:754)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:767)
	...
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:993)
	...
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	...
java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	...
	at de.dg.logging.BaggagePropagator.proceedWithBaggage(BaggagePropagator.java:74)
	at de.dg.logging.BaggagePropagator.propagateBaggage(BaggagePropagator.java:54)
	at de.dg.logging.configuration.BaggageInterceptorConfig.propagateBaggage(BaggageInterceptorConfig.java:23)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	...
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	...
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	...
Caused by: java.sql.SQLException: Connection has already been closed.
	at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:121)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:107)
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:89)
	at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:107)
	at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
	at jdk.proxy3/jdk.proxy3.$Proxy580.prepareStatement(Unknown Source)
	at org.springframework.jdbc.core.JdbcTemplate$SimplePreparedStatementCreator.createPreparedStatement(JdbcTemplate.java:1719)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:656)
	... 184 more

There is no accompanying error or warning. I can't spend much more time on database debugging and thus might have to downgrade jaybird again, until we have managed to upgrade our database server. The hope is, that the integration with Firebird 5.0 produces less connection problems - or are those problems independent of the server version?

[mrotteveel]

Fixing the logging of that warning "Specified statement was not created by this connection" will not fix that connection closed issue. The warning is either another symptom of the problem (so, not the cause) or something entirely unrelated to the problem you're seeing.

Are you sure this isn't still related to the Tomcat removeAbandonedTimeout issue that was the underlying cause of #898? The stacktrace you show seems to be the same, and the exception originates within Tomcat's pool code, not within Jaybird.

[mrotteveel]

Without identifying the actual cause, it's impossible to tell that upgrading to Firebird 5.0 would solve it, but my gut feeling says no.

[ambition-consulting]

Fixing the logging of that warning "Specified statement was not created by this connection" will not fix that connection closed issue. The warning is either another symptom of the problem (so, not the cause) or something entirely unrelated to the problem you're seeing.

Are you sure this isn't still related to the Tomcat removeAbandonedTimeout issue that was the underlying cause of #898? The stacktrace you show seems to be the same, and the exception originates within Tomcat's pool code, not within Jaybird.

I have increased the removeAbandonedTimeout to 600, but not set it to false yet. I will try setting to false next. Thanks again for your thoughts - highly appreciated.