[CONFSERVER-56098] Confluence attempts ALTER statement on AO tables intermittently at runtime and/or on restart

Type: Bug
Resolution: Tracked Elsewhere
Priority: Medium
Fix Version/s: None
Affects Version/s: 6.4.3, 6.6.6, 6.6.7, 6.10.1, 6.13.1
Component/s: Server - Platform
Labels:
None

Support reference count:
9
Symptom Severity:
Severity 3 - Minor
UIS:
4
Bug Fix Policy:
View Atlassian Server bug fix policy

Summary

This bug is relatively similar in behavior to the one reported in ~~JRASERVER-63126~~ in which restarts can perform unnecessary ALTER statements on the AO table. If these tables are large, an error can occur when multiple processes attempt to access the same db resources. Moreover, this behavior can occur at runtime in edge cases

Environment

Confluence 6.0+ Server or Data Center
Some plugins creating table with LONGTEXT columns: eg: DVCS, webhook

Steps to Reproduce

Set up Confluence
Enable AO debug logging or DB SQL logging
Restart Confluence

Expected Results

Confluence doesn't do unnecessary table modification

Actual Results

During Startup

Confluence does unnecessary table modification. If those tables are large, it can cause example error:

Caused by: Error : 54, Position : 12, Sql = ALTER TABLE "AO_950DC3_TC_SUBCALS" MODIFY ("CREATED" DEFAULT 0), OriginalSql = ALTER TABLE "AO_950DC3_TC_SUBCALS" MODIFY ("CREATED" DEFAULT 0), Error Msg = ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired

At Runtime

Confluence can throw the following error

2019-02-11 03:57:05,059 DEBUG [http-nio-1101-exec-4] [plugins.createcontent.exceptions.RestExceptionMapper] toResponse create-content-plugin exception
 -- referer: https://confluence-base-url/confluence/pages/editpage.action?pageId=123456789 | url: /confluence/rest/create-dialog/1.0/blueprints/web-items | traceId: 061ac753dbbb1bc8 | userName: someuser
com.atlassian.activeobjects.internal.ActiveObjectsInitException: bundle [com.atlassian.confluence.plugins.confluence-create-content-plugin]
	at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:95)
	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:87)
	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:71)
	at com.atlassian.confluence.vcache.VCacheRequestContextOperations.lambda$withRequestContext$1(VCacheRequestContextOperations.java:59)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.atlassian.activeobjects.internal.ActiveObjectsSqlException: There was a SQL exception thrown by the Active Objects library:
Database:
	- name:Oracle
	- version:Oracle Database 12c Enterprise Edition Release - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options
	- minor version:1
	- major version:12
Driver:
	- name:Oracle JDBC driver
	- version:x.x

java.sql.SQLException: ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired

	at com.atlassian.activeobjects.internal.EntityManagedActiveObjects.migrate(EntityManagedActiveObjects.java:53)
	at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory$1.doInTransaction(AbstractActiveObjectsFactory.java:77)
	at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory$1.doInTransaction(AbstractActiveObjectsFactory.java:72)
	at com.atlassian.sal.core.transaction.HostContextTransactionTemplate$1.doInTransaction(HostContextTransactionTemplate.java:21)
	at com.atlassian.sal.spring.component.SpringHostContextAccessor$1.doInTransaction(SpringHostContextAccessor.java:71)
	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
	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:87)
	at com.atlassian.confluence.impl.vcache.VCacheRequestContextManager.doInRequestContext(VCacheRequestContextManager.java:71)
	at com.atlassian.confluence.spring.transaction.interceptor.ConfluenceSpringHostContextAccessor.doInTransaction(ConfluenceSpringHostContextAccessor.java:72)
	at sun.reflect.GeneratedMethodAccessor257.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
	at com.sun.proxy.$Proxy316.doInTransaction(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor257.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:136)
	at com.sun.proxy.$Proxy316.doInTransaction(Unknown Source)
	at com.atlassian.sal.core.transaction.HostContextTransactionTemplate.execute(HostContextTransactionTemplate.java:18)
	at sun.reflect.GeneratedMethodAccessor258.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
	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:179)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	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:179)
	at org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
	at com.sun.proxy.$Proxy911.execute(Unknown Source)
	at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory.create(AbstractActiveObjectsFactory.java:72)
	at com.atlassian.activeobjects.internal.DelegatingActiveObjectsFactory.create(DelegatingActiveObjectsFactory.java:32)
	at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:91)
	... 9 more
Caused by: java.sql.SQLException: ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired

	at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494)
	at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446)
	at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054)
	at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623)
	at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252)
	at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612)
	at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213)
	at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37)
	at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896)
	at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119)
	at oracle.jdbc.driver.OracleStatement.executeUpdateInternal(OracleStatement.java:1661)
	at oracle.jdbc.driver.OracleStatement.executeLargeUpdate(OracleStatement.java:1626)
	at oracle.jdbc.driver.OracleStatement.executeUpdate(OracleStatement.java:1613)
	at oracle.jdbc.driver.OracleStatementWrapper.executeUpdate(OracleStatementWrapper.java:282)
	at org.apache.tomcat.dbcp.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:233)
	at org.apache.tomcat.dbcp.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:233)
	at net.java.ao.DatabaseProvider.executeUpdate(DatabaseProvider.java:2238)
	at net.java.ao.DatabaseProvider.executeUpdateForAction(DatabaseProvider.java:2294)
	at net.java.ao.DatabaseProvider.executeUpdatesForActions(DatabaseProvider.java:2266)
	at net.java.ao.schema.SchemaGenerator.migrate(SchemaGenerator.java:91)
	at net.java.ao.EntityManager.migrate(EntityManager.java:128)
	at com.atlassian.activeobjects.internal.EntityManagedActiveObjects.migrate(EntityManagedActiveObjects.java:51)
	... 54 more
Caused by: Error : 54, Position : 12, Sql = ALTER TABLE "AO_54C900_C_TEMPLATE_REF" MODIFY ("TEMPLATE_ID" DEFAULT 0), OriginalSql = ALTER TABLE "AO_54C900_C_TEMPLATE_REF" MODIFY ("TEMPLATE_ID" DEFAULT 0), Error Msg = ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired

	at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:498)
	... 75 more

Notes

This is a bug in the AO library which allows for those unnecessary queries to run:

MySQL bug is caused by bug in AO framework, see AO-3406
ALTER table for Oracle, see AO-3460, AO-3463 and AO-3464

Workaround

Restarting the node experiencing this behavior should resolve this issue temporarily.

is incorporated by

CONFSERVER-57375 Confluence modifies tables with active objects on every restart

Closed

relates to

CONFSERVER-57375 Confluence modifies tables with active objects on every restart

Closed

PSR-257 You do not have permission to view this issue

Nhan Dang added a comment - 15/May/2019 3:07 AM - edited

The Oracle bugs were fixed in AO 1.5.2 (bundled in Confluence 6.13 and above). The MySQL one was fixed in AO 2.0.0 (watch ~~CONFSERVER-57375~~ for progress).

Nhan Dang added a comment - 15/May/2019 3:07 AM - edited The Oracle bugs were fixed in AO 1.5.2 (bundled in Confluence 6.13 and above). The MySQL one was fixed in AO 2.0.0 (watch CONFSERVER-57375 for progress).

Confluence Data Center

Details

Description

Summary

Environment

Steps to Reproduce

Expected Results

Actual Results

During Startup

At Runtime

Notes

Workaround

Attachments

Issue Links

Forms

Activity

Collapse comment: Nhan Dang added a comment - 15/May/2019 3:07 AM, Edited by Nhan Dang - 15/May/2019 3:08 AM

Expand comment: Nhan Dang added a comment - 15/May/2019 3:07 AM, Edited by Nhan Dang - 15/May/2019 3:08 AM

People

Dates