Plugin upgrades fail in Postgres because of stale prepared statements cache

XMLWordPrintable

    • Type: Bug
    • Resolution: Unresolved
    • Priority: Low
    • None
    • Affects Version/s: 7.14.0
    • None
    • Severity 2 - Major

      Problem definition

      Plugin upgrades usually involve the AO framework to issue multiple queries like below mixed with DDL queries if columns are added/changed/deleted:

      select * from AO_21D670_WHITELIST_RULES;

      This may become a problem in Postgres if 1/ server prepared statements are used and 2/ a physical connection is reused (e.g. the use of connection pools): there is a chance that a cached query plan referring to the old table will be used after the DDL has altered the table resulting in cached plan must not change result type error from Postgres.

      2021-10-17 21:56:51,324 WARN [active-objects-init-system tenant-0] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions:
        ->[PluginReadWriteTx]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #1240317474)
       -- url: /confluence/longrunningtaskxml.action | traceId: 024d01439ac993fd | userName: admin | action: longrunningtaskxml
      2021-10-17 21:56:51,372 ERROR [active-objects-init-system tenant-0] [springframework.transaction.support.TransactionTemplate] rollbackOnException Application exception overridden by rollback exception
       -- url: /confluence/longrunningtaskxml.action | traceId: 024d01439ac993fd | userName: admin | action: longrunningtaskxml
      java.lang.RuntimeException: Could not read fields for table AO_A0B856_WEB_HOOK_LISTENER_AO
      	at net.java.ao.schema.helper.DatabaseMetaDataReaderImpl.getFields(DatabaseMetaDataReaderImpl.java:141)
      	at net.java.ao.schema.ddl.SchemaReader.readFields(SchemaReader.java:126)
      	at net.java.ao.schema.ddl.SchemaReader.readTable(SchemaReader.java:110)
      	at net.java.ao.schema.ddl.SchemaReader.access$000(SchemaReader.java:62)
      	at net.java.ao.schema.ddl.SchemaReader$1.apply(SchemaReader.java:99)
      	at net.java.ao.schema.ddl.SchemaReader$1.apply(SchemaReader.java:97)
      	at com.google.common.collect.Iterators$6.transform(Iterators.java:785)
      	at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:47)
      	at com.google.common.collect.Iterators.addAll(Iterators.java:358)
      	at com.google.common.collect.Lists.newArrayList(Lists.java:147)
      	at com.google.common.collect.Lists.newArrayList(Lists.java:133)
      	at net.java.ao.schema.ddl.SchemaReader.readSchema(SchemaReader.java:97)
      	at net.java.ao.schema.ddl.SchemaReader.readSchema(SchemaReader.java:88)
      	at net.java.ao.schema.ddl.SchemaReader.readSchema(SchemaReader.java:81)
      	at net.java.ao.schema.SchemaGenerator.generateImpl(SchemaGenerator.java:107)
      	at net.java.ao.schema.SchemaGenerator.migrate(SchemaGenerator.java:84)
      	at net.java.ao.EntityManager.migrate(EntityManager.java:131)
      	at com.atlassian.activeobjects.internal.EntityManagedActiveObjects.migrate(EntityManagedActiveObjects.java:52)
      	at com.atlassian.webhooks.internal.dao.MigrateToV1Task.upgrade(MigrateToV1Task.java:43)
      	at com.atlassian.activeobjects.internal.DataSourceProviderActiveObjectsFactory$PostgresActiveObjectsUpgradeTask.configureConnectionAndRun(DataSourceProviderActiveObjectsFactory.java:241)
      	at com.atlassian.activeobjects.internal.DataSourceProviderActiveObjectsFactory$PostgresActiveObjectsUpgradeTask.upgrade(DataSourceProviderActiveObjectsFactory.java:188)
      	at com.atlassian.activeobjects.internal.ActiveObjectUpgradeManagerImpl.lambda$upgrade$0(ActiveObjectUpgradeManagerImpl.java:64)
      	at com.atlassian.sal.core.transaction.HostContextTransactionTemplate$1.doInTransaction(HostContextTransactionTemplate.java:21)
      	at com.atlassian.sal.spring.component.SpringHostContextAccessor.lambda$doInTransaction$0(SpringHostContextAccessor.java:70)
      	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
      	at com.atlassian.sal.spring.component.SpringHostContextAccessor.doInTransaction(SpringHostContextAccessor.java:68)
      	at com.atlassian.confluence.spring.transaction.interceptor.ConfluenceSpringHostContextAccessor.access$001(ConfluenceSpringHostContextAccessor.java:21)
      	at com.atlassian.confluence.spring.transaction.interceptor.ConfluenceSpringHostContextAccessor.lambda$doInTransaction$3(ConfluenceSpringHostContextAccessor.java:72)
      	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContextInternal(VCacheRequestContextManager.java:84)
      	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:68)
      	at com.atlassian.confluence.spring.transaction.interceptor.ConfluenceSpringHostContextAccessor.doInTransaction(ConfluenceSpringHostContextAccessor.java:72)
      	at com.atlassian.sal.core.transaction.HostContextTransactionTemplate.execute(HostContextTransactionTemplate.java:18)
      	at jdk.internal.reflect.GeneratedMethodAccessor363.invoke(Unknown Source)
      	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      	at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
      	at com.sun.proxy.$Proxy380.execute(Unknown Source)
      	at jdk.internal.reflect.GeneratedMethodAccessor363.invoke(Unknown Source)
      	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343)
      	at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.doInvoke(ServiceInvoker.java:56)
      	at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:60)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
      	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
      	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
      	at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:70)
      	at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:53)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
      	at org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
      	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
      	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
      	at com.sun.proxy.$Proxy1270.execute(Unknown Source)
      	at com.atlassian.activeobjects.internal.SalTransactionManager.inTransaction(SalTransactionManager.java:42)
      	at com.atlassian.activeobjects.internal.AbstractLoggingTransactionManager.doInTransaction(AbstractLoggingTransactionManager.java:16)
      	at com.atlassian.activeobjects.internal.EntityManagedActiveObjects.executeInTransaction(EntityManagedActiveObjects.java:214)
      	at com.atlassian.activeobjects.internal.ActiveObjectUpgradeManagerImpl.upgrade(ActiveObjectUpgradeManagerImpl.java:62)
      	at com.atlassian.activeobjects.internal.ActiveObjectUpgradeManagerImpl.upgrade(ActiveObjectUpgradeManagerImpl.java:34)
      	at com.atlassian.activeobjects.internal.DataSourceProviderActiveObjectsFactory.upgrade(DataSourceProviderActiveObjectsFactory.java:84)
      	at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory.create(AbstractActiveObjectsFactory.java:65)
      	at com.atlassian.activeobjects.internal.DelegatingActiveObjectsFactory.create(DelegatingActiveObjectsFactory.java:32)
      	at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:91)
      	at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:86)
      	at com.atlassian.sal.core.executor.ThreadLocalDelegateCallable.call(ThreadLocalDelegateCallable.java:38)
      	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContextInternal(VCacheRequestContextManager.java:84)
      	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:68)
      	at com.atlassian.confluence.vcache.VCacheRequestContextOperations.lambda$withRequestContext$1(VCacheRequestContextOperations.java:59)
      	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
      	at java.base/java.lang.Thread.run(Thread.java:829)
      Caused by: org.postgresql.util.PSQLException: ERROR: cached plan must not change result type
      	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
      	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
      	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
      	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
      	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
      	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
      	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
      	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
      	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
      	at net.java.ao.schema.helper.DatabaseMetaDataReaderImpl.getResultSetMetaData(DatabaseMetaDataReaderImpl.java:271)
      	at net.java.ao.schema.helper.DatabaseMetaDataReaderImpl.getFields(DatabaseMetaDataReaderImpl.java:91)
      	... 74 more
      

      Workaround

      1. Restart Confluence might help since the stale cache is caused by a race condition.
      1. Disable server prepared statements cache in Postgres by setting prepareThreshold=0 in the connection URL. This may incur some performance penalty!

            Assignee:
            Unassigned
            Reporter:
            Nhan Dang
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: