Log file in DEBUG mode flooded with Cannot change transaction read-only property in the middle of a transaction

[josegar74]

Describe the bug

Tested with a Postgres database with main branch.

Enabling the DEBUG log mode for development and accessing the search application at least, the log file is flooded with this type of exceptions, making it really unusable.

2022-10-12T05:01:08,625 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7e974ac8]
2022-10-12T05:01:08,625 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Initiating transaction commit
2022-10-12T05:01:08,625 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Committing JPA transaction on EntityManager [SessionImpl(1753322716<open>)]
2022-10-12T05:01:08,628 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Resetting read-only flag of JDBC Connection [1659623692, URL=jdbc:postgresql://localhost:5432/geonetwork?, UserName=postgres, PostgreSQL JDBC Driver]
2022-10-12T05:01:08,628 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Closing JPA EntityManager [SessionImpl(1753322716<open>)] after transaction
2022-10-12T05:01:08,640 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Creating new transaction with name [org.fao.geonet.repository.GeonetRepositoryImpl.findById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2022-10-12T05:01:08,641 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Opened new EntityManager [SessionImpl(1111669151<open>)] for JPA transaction
2022-10-12T05:01:08,642 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Setting JDBC Connection [1167262595, URL=jdbc:postgresql://localhost:5432/geonetwork?, UserName=postgres, PostgreSQL JDBC Driver] read-only
2022-10-12T05:01:08,642 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Could not set JDBC Connection read-only
org.postgresql.util.PSQLException: Cannot change transaction read-only property in the middle of a transaction.
        at org.postgresql.jdbc.PgConnection.setReadOnly(PgConnection.java:787) ~[postgresql-42.3.3.jar:42.3.3]
        at org.apache.commons.dbcp2.DelegatingConnection.setReadOnly(DelegatingConnection.java:561) ~[commons-dbcp2-2.7.0.jar:2.7.0]
        at org.apache.commons.dbcp2.DelegatingConnection.setReadOnly(DelegatingConnection.java:561) ~[commons-dbcp2-2.7.0.jar:2.7.0]
        at org.apache.commons.dbcp2.DelegatingConnection.setReadOnly(DelegatingConnection.java:561) ~[commons-dbcp2-2.7.0.jar:2.7.0]
        at org.springframework.jdbc.datasource.DataSourceUtils.prepareConnectionForTransaction(DataSourceUtils.java:188) ~[spring-jdbc-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:175) ~[spring-orm-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402) ~[spring-orm-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:574) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:361) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139) ~[spring-tx-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:178) ~[spring-data-jpa-2.2.13.RELEASE.jar:2.2.13.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at com.sun.proxy.$Proxy206.findById(Unknown Source) ~[?:?]
        at org.fao.geonet.kernel.setting.SettingManager.getValue(SettingManager.java:193) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.fao.geonet.kernel.setting.SettingManager.getValue(SettingManager.java:181) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.fao.geonet.kernel.setting.SettingManager.getSiteId(SettingManager.java:392) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.fao.geonet.resources.ResourceFilter$Instance.<init>(ResourceFilter.java:97) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.fao.geonet.resources.ResourceFilter.doFilter(ResourceFilter.java:72) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.fao.geonet.web.CORSResponseFilter.doFilter(CORSResponseFilter.java:129) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.fao.geonet.monitor.webapp.WebappMetricsFilter.doFilter(WebappMetricsFilter.java:121) ~[gn-health-monitor-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.fao.geonet.monitor.webapp.MetricsRegistryInitializerFilter.doFilter(MetricsRegistryInitializerFilter.java:58) ~[gn-health-monitor-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.fao.geonet.web.XFrameOptionsFilter.doFilter(XFrameOptionsFilter.java:110) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176) ~[urlrewritefilter-4.0.3.jar:4.0.3]
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145) ~[urlrewritefilter-4.0.3.jar:4.0.3]
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92) ~[urlrewritefilter-4.0.3.jar:4.0.3]
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394) ~[urlrewritefilter-4.0.3.jar:4.0.3]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) ~[spring-security-web-5.7.3.jar:5.7.3]
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:186) ~[spring-security-web-5.7.3.jar:5.7.3]
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[spring-web-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[spring-web-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at jeeves.config.springutil.JeevesDelegatingFilterProxy.doFilter(JeevesDelegatingFilterProxy.java:74) ~[gn-core-4.2.2-SNAPSHOT.jar:?]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.20.RELEASE.jar:5.2.20.RELEASE]
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[jetty-security-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.48.v20220622.jar:9.4.46.v20220331]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[jetty-servlet-9.4.48.v20220622.jar:9.4.46.v20220331]
...

To Reproduce Steps to reproduce the behavior:

1. Login as Administrator user
2. Go to the settings page and change the log level to DEBUG
3. Access the home page
4. The log file is flooded with the exceptions described previously, making quite difficult to use it.

Unclear which code is trying to "change transaction read-only property in the middle of a transaction".

[jeanpommier]

Hi @josegar74 Any insight about this ? I'm working on a 3.12.7 instance, that shows the same behaviour.

[jodygarnett]

The above looks like a connection pool setting "dbcp2" - and is actually a little alarming.

The connection pool is trying to set a connection to readonly mode.

However the pool is there to recycle connections, so it has acquired a connection with a transaction already started. I sure hope previous code did not start a transaction, and then return the connection to the pool with a transaction already in progress.

Does geonetwork manage its own connection pool, or is it obtaining this from Tomcat or Jetty? How was your postgres connection configured?