Negative buffer size on Firebird 2.5 if information response is 32KiB or greater

[mrotteveel]

Split off from #876

could this problem also apply to 5.0.9 jaybird? we have been experiencing a lot of connection problems after updating from 5.0.1.java8 to 5.0.9.java 11 (we are still stuck with a firebird 2.5 unfortunately).

in particular, we get

Could not open JDBC Connection for transaction; nested exception is org.firebirdsql.jdbc.FBSQLException: You cannot getAutoCommit on an unassociated closed connection. org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is org.firebirdsql.jdbc.FBSQLException: You cannot getAutoCommit on an unassociated closed connection. at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:313) at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction

and

PreparedStatementCallback; SQL [whatever]; This connection is closed and cannot be used now.; nested exception is org.firebirdsql.jdbc.FBSQLException: This connection is closed and cannot be used now. at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:107) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73) at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate

Interestingly, this error did not emerge right after deployment, but 6 hours later when the first heavy load nightly batch job was scheduled.

After that, it randomly and inconsistently caused problems - sometimes on the first jdbc query, sometimes later. We obviously checked our code for unintentional connection closing, but literally nothing changed there - only the version update of jaybird.

---

The very first exception I have received might be interesting though:

SQLNonTransientConnectionException: Unsupported or unexpected operation code 352583681 in processOperation [SQLState:08000, ISC error code:337248276]
...
Caused by: java.sql.SQLNonTransientConnectionException: Unsupported or unexpected operation code 352583681 in processOperation [SQLState:08000, ISC error code:337248276] at org.firebirdsql.gds.ng.FbExceptionBuilder$Type$4.createSQLException(FbExceptionBuilder.java:664) at org.firebirdsql.gds.ng.FbExceptionBuilder$ExceptionInformation.toSQLException(FbExceptionBuilder.java:571) at org.firebirdsql.gds.ng.FbExceptionBuilder.toSQLException(FbExceptionBuilder.java:309) at org.firebirdsql.gds.ng.wire.AbstractWireOperations.processOperation(AbstractWireOperations.java:217) at org.firebirdsql.gds.ng.wire.AbstractWireOperations.readOperationResponse(AbstractWireOperations.java:175) at org.firebirdsql.gds.ng.wire.AbstractWireOperations.readResponse(AbstractWireOperations.java:169) at org.firebirdsql.gds.ng.wire.AbstractFbWireDatabase.readResponse(AbstractFbWireDatabase.java:222) at org.firebirdsql.gds.ng.wire.version10.V10Transaction.finishTransaction(V10Transaction.java:135) at org.firebirdsql.gds.ng.wire.version10.V10Transaction.rollback(V10Transaction.java:105) at org.firebirdsql.jaybird.xca.FBManagedConnection.internalRollback(FBManagedConnection.java:886) at org.firebirdsql.jaybird.xca.FBLocalTransaction.rollback(FBLocalTransaction.java:127) at org.firebirdsql.jdbc.InternalTransactionCoordinator$AutoCommitCoordinator.statementCompleted(InternalTransactionCoordinator.java:362) at org.firebirdsql.jdbc.InternalTransactionCoordinator.statementCompleted(InternalTransactionCoordinator.java:134) at org.firebirdsql.jdbc.FBStatement.notifyStatementCompleted(FBStatement.java:286) at org.firebirdsql.jdbc.FBPreparedStatement.notifyStatementCompleted(FBPreparedStatement.java:167) at org.firebirdsql.jdbc.FBPreparedStatement.<init>(FBPreparedStatement.java:149) at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:797) at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:709) at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:703) at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:294) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81) at jdk.proxy3/jdk.proxy3.$Proxy583.prepareStatement(Unknown Source) at org.springframework.jdbc.core.PreparedStatementCreatorFactory$PreparedStatementCreatorImpl.createPreparedStatement(PreparedStatementCreatorFactory.java:235) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:646) ... 112 more

I got this exception multiple times, in each parallel thread executed for the batch job.

---

What I cannot understand though, is that when I was hotfixing later, restarting the application (including the tomcat application server) did result in the error showing up right after deployment, unlike the first time, where it only occured after a while. Database connectivity should have been arround the same, since we deployed both with blue/green during prime time.

And restarting firebird did not help either.

Originally posted by @ambition-consulting in #876

[ambition-consulting]

Please note, that our application unfortunately is by far not the only application connecting to the database. I doubt it's a database problem (due to the failed restart approach), but if so we have little chance in reproducing.

Also, our application is isolated from other java applications due to using it's own application server / jndi setup, so we can be sure about no other application interfering with the jdbc connection.

[mrotteveel]

That error would suggest that Jaybird has a protocol error somewhere: it reads too many or too few bytes in a response, causing a subsequent read to get incorrect bytes (in this case for the operation code, which identifies the response). That would indeed forcibly close the connection as that is not recoverable.

Is it possible that the connection is accessed by multiple threads concurrently, or maybe a Statement.cancel() used somewhere?

[mrotteveel]

Reformatted exception from initial comment:

SQLNonTransientConnectionException: Unsupported or unexpected operation code 352583681 in processOperation [SQLState:08000, ISC error code:337248276]
...
Caused by: java.sql.SQLNonTransientConnectionException: Unsupported or unexpected operation code 352583681 in processOperation [SQLState:08000, ISC error code:337248276]
 at org.firebirdsql.gds.ng.FbExceptionBuilder$Type$4.createSQLException(FbExceptionBuilder.java:664)
 at org.firebirdsql.gds.ng.FbExceptionBuilder$ExceptionInformation.toSQLException(FbExceptionBuilder.java:571)
 at org.firebirdsql.gds.ng.FbExceptionBuilder.toSQLException(FbExceptionBuilder.java:309)
 at org.firebirdsql.gds.ng.wire.AbstractWireOperations.processOperation(AbstractWireOperations.java:217)
 at org.firebirdsql.gds.ng.wire.AbstractWireOperations.readOperationResponse(AbstractWireOperations.java:175)
 at org.firebirdsql.gds.ng.wire.AbstractWireOperations.readResponse(AbstractWireOperations.java:169)
 at org.firebirdsql.gds.ng.wire.AbstractFbWireDatabase.readResponse(AbstractFbWireDatabase.java:222) at org.firebirdsql.gds.ng.wire.version10.V10Transaction.finishTransaction(V10Transaction.java:135)
 at org.firebirdsql.gds.ng.wire.version10.V10Transaction.rollback(V10Transaction.java:105)
 at org.firebirdsql.jaybird.xca.FBManagedConnection.internalRollback(FBManagedConnection.java:886)
 at org.firebirdsql.jaybird.xca.FBLocalTransaction.rollback(FBLocalTransaction.java:127)
 at org.firebirdsql.jdbc.InternalTransactionCoordinator$AutoCommitCoordinator.statementCompleted(InternalTransactionCoordinator.java:362)
 at org.firebirdsql.jdbc.InternalTransactionCoordinator.statementCompleted(InternalTransactionCoordinator.java:134)
 at org.firebirdsql.jdbc.FBStatement.notifyStatementCompleted(FBStatement.java:286)
 at org.firebirdsql.jdbc.FBPreparedStatement.notifyStatementCompleted(FBPreparedStatement.java:167)
 at org.firebirdsql.jdbc.FBPreparedStatement.<init>(FBPreparedStatement.java:149)
 at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:797)
 at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:709)
 at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:703)
 at org.firebirdsql.jdbc.FBConnection.prepareStatement(FBConnection.java:294)
 at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
 at java.base/java.lang.reflect.Method.invoke(Method.java:580)
 at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
 at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
 at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
 at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
 at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
 at jdk.proxy3/jdk.proxy3.$Proxy583.prepareStatement(Unknown Source)
 at org.springframework.jdbc.core.PreparedStatementCreatorFactory$PreparedStatementCreatorImpl.createPreparedStatement(PreparedStatementCreatorFactory.java:235)
 at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:646) ... 112 more

[mrotteveel]

It's a pity that the exception handling in the FBPreparedStatement constructor doesn't log or otherwise preserve the original exception if the call to notifyStatementCompleted fails.

@ambition-consulting Do you by any chance have configured connection property soTimeout, and if so, what is it set to?

[ambition-consulting]

We run computations in parallel (for more than 100 entries) for up to 1500 entries at a time (due to firebirds restriction on IN operator), and this computation is run in parallel on at most 12 parallel REST calls. However, for all 12 calls the data is loaded for all 1500 computations in the beginning (in parallel, which should easily fit into the 300 max active connections configured on JNDI).

This is our JNDI configuration:

<Resource
        name="jdbc/foo"
        auth="Container"
        type="javax.sql.DataSource"
        factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
        initialSize="30"
        maxActive="300"
        maxIdle="100"
        minIdle="10"
        timeBetweenEvictionRunsMillis="34000"
        minEvictableIdleTimeMillis="60000"
        validationQuery="SELECT 1 FROM RDB$DATABASE"
        validationInterval="34000"
        testOnBorrow="true"
        removeAbandoned="true"
        removeAbandonedTimeout="200"
        connectionTimeout="30000"
        driverClassName="org.firebirdsql.jdbc.FBDriver" />

This is our connection pool dashboard at the time of the exception:

or more specifically

This job has been running successfully with 5.0.1.java8 for 3 months and failed on the first night for 5.0.9.java11.

Interestingly, the first two exceptions in the batch fail at the very same millisecond:

We are using an extended Spring JDBC (org.springframework:spring-jdbc:5.3.39)template, which will commit a OpenTelemetry traceId and user information to the transaction context using

private final static String SET_CONTEXT_STATEMENT = "select rdb$set_context(?, ?, ?) from rdb$database";

    @Override    
    public <T> T query(String sql, @Nullable PreparedStatementSetter pss,
        ResultSetExtractor<T> rse) throws DataAccessException {
        if (sql.toUpperCase().startsWith("EXECUTE") || sql.toUpperCase().startsWith("INSERT")) {
            updateTransactionContext();
        }
        return super.query(sql, pss, rse);
    }

    @Override
    protected int update(final PreparedStatementCreator psc, @Nullable final PreparedStatementSetter pss) {
        updateTransactionContext();
        return super.update(psc, pss);
    }

(...)
private void updateTransactionContext() {
(...)
super.queryForList(SET_CONTEXT_STATEMENT, Integer.class, FbContextType.USER_TRANSACTION.name(),
                TRACE_ID_VARNAME, traceIdAndTime);
(...)
}

This tracing context is then used in our audit triggers to save the user and transaction id, under which a update was executed.

I have carefully looked at the parallel fetching of data for computation (under which the exception occured), and none of it is annotated as transactional - nor does anything here actually commit a change, it's all just SELECTs.

[ambition-consulting]

Any suggestion on how to add the connection ID to the logs? I have no idea where to get it from.

[mrotteveel]

Unfortunately, connections don't really have a user-accessible ID (the closest currently is their hashcode, but that could be obscured by the connection pool wrapping it). Is the failure triggered by executing the SET_CONTEXT_STATEMENT, or by something else?

[ambition-consulting]

I doubt it, but can test it, since this can be toggled of.

[ambition-consulting]

It's a pity that the exception handling in the FBPreparedStatement constructor doesn't log or otherwise preserve the original exception if the call to notifyStatementCompleted fails.

@ambition-consulting Do you by any chance have configured connection property soTimeout, and if so, what is it set to?

not that I am aware of, and I have access to everything relevant.

I have learnt this relates to the jdbc connection string. No, we only set encoding and roles there.

[mrotteveel]

I've published a jaybird-5.0.10-SNAPSHOT to https://central.sonatype.com/repository/maven-snapshots/ and attached the distribution zip to this comment. This adds some extra logging in the FBPreparedStatement constructor on DEBUG (so you may need to increase your log level to see it!). This is essentially Jaybird 5.0.9 + that logging.

jaybird-5.0.10.java11-SNAPSHOT.zip

[mrotteveel]

The logging is what's committed in 98a62ed

[ambition-consulting]

I will show results with increased log levels soon.

My test setup allowed me to find two other relevant logs (on WARN level)

org.firebirdsql.jdbc.FBSQLException: This connection is closed and cannot be used now.
at org.firebirdsql.jdbc.FBConnection.checkValidity(FBConnection.java:141)
at org.firebirdsql.jdbc.FBConnection.clearWarnings(FBConnection.java:636)
at org.apache.tomcat.jdbc.pool.PooledConnection.clearWarnings(PooledConnection.java:813)
at org.apache.tomcat.jdbc.pool.ConnectionPool.returnConnection(ConnectionPool.java:934)
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:100)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:69)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at jdk.proxy3/jdk.proxy3.$Proxy607.close(Unknown Source)
at org.springframework.jdbc.datasource.DataSourceUtils.doCloseConnection(DataSourceUtils.java:407)
at org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection(DataSourceUtils.java:394)
at org.springframework.jdbc.datasource.DataSourceUtils.releaseConnection(DataSourceUtils.java:361)
at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:373)
at org.springframework.jdbc.support.SQLErrorCodesFactory.resolveErrorCodes(SQLErrorCodesFactory.java:236)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.lambda$setDataSource$0(SQLErrorCodeSQLExceptionTranslator.java:138)
at org.springframework.util.function.SingletonSupplier.get(SingletonSupplier.java:97)
at org.springframework.util.function.SupplierUtils.resolve(SupplierUtils.java:40)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.getSqlErrorCodes(SQLErrorCodeSQLExceptionTranslator.java:169)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:191)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1575)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:738)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:794)
at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.query(NamedParameterJdbcTemplate.java:212)
at foo
at foo
at foo
at foo
at foo
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:792)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:762)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:762)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:707)
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.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:903)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:809)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1072)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:965)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.togglz.servlet.TogglzFilter.doFilter(TogglzFilter.java:110)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at foo
at foo
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:121)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:115)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:149)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:91)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at foo
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:660)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:1583)

and

org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData; nested exception is org.firebirdsql.jdbc.FBSQLException: This connection is closed and cannot be used now.
at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:366)
at org.springframework.jdbc.support.SQLErrorCodesFactory.resolveErrorCodes(SQLErrorCodesFactory.java:236)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.lambda$setDataSource$0(SQLErrorCodeSQLExceptionTranslator.java:138)
at org.springframework.util.function.SingletonSupplier.get(SingletonSupplier.java:97)
at org.springframework.util.function.SupplierUtils.resolve(SupplierUtils.java:40)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.getSqlErrorCodes(SQLErrorCodeSQLExceptionTranslator.java:169)
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:191)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1575)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:738)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:794)
at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.query(NamedParameterJdbcTemplate.java:212)
at foo
at foo
at foo
at foo
at foo
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:792)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:762)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:762)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:707)
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.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:903)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:809)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1072)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:965)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.togglz.servlet.TogglzFilter.doFilter(TogglzFilter.java:110)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at foo
at foo
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:121)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:115)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:149)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:91)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at foo
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:660)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:798)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:1583) Caused by: org.firebirdsql.jdbc.FBSQLException: This connection is closed and cannot be used now.
at org.firebirdsql.jdbc.FBConnection.checkValidity(FBConnection.java:141)
at org.firebirdsql.jdbc.FBConnection.getMetaData(FBConnection.java:555)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at jdk.proxy3/jdk.proxy3.$Proxy607.getMetaData(Unknown Source)
at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:340) ... 121 more

Both probably are just a result of the closed connection.

[ambition-consulting]

Using

<logger name="org.firebirdsql.jdbc.FBPreparedStatement" level="DEBUG"/>

I do not get any new DEBUG level logs, I think. This is the right name, correct? Or is it FBCallableStatement? Not sure what getClass resolves to.

I will try to remove jaybird from my application dependencies, so it definately picks it up from the tomcat library for JNDI.

Also, I will try out

<logger name="org.firebirdsql.jdbc" level="DEBUG"/>

instead...

Actually, I will just rebuild with info level - no interest in logback configuration problems.