Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Obsolete
Priority: Low
Fix Version/s: None
Affects Version/s: 2.2.3
Component/s: Backend / Domain Model
Labels:
- jirastudio

Symptom Severity:
Severity 3 - Minor
Bug Fix Policy:
View Atlassian Server bug fix policy

Description

This issue originates from investigations into JST-4983 - see there for the full context.

In Studio, we have a Crowd plugin which provides:

A set of Upgrade Tasks (implementations of SAL's PluginUpgradeTask), one of which switches from the database token store to the in-memory token store, using TokenManager.setUsingDatabaseStorage(false). See here:
A servlet to trigger the upgrade tasks. This is required because of CWD-1895 (Crowd doesn't restart the plugin system after a restore).

In Studio CI, we hit that servlet after restoring test fixtures into Crowd. This request intermittently results in an 500 response. The log shows the following failure:

2011-06-01 06:34:04,778 http-4990-7 DEBUG [org.hibernate.SQL] delete from cwd_token
2011-06-01 06:34:04,779 http-4990-7 INFO [crowd.manager.token.TokenManagerImpl] Finished switch to in-memory token storage
2011-06-01 06:34:04,779 http-4990-7 INFO [sal.core.upgrade.PluginUpgrader] Upgraded plugin com.atlassian.studio.crowd.plugin to version 9 - Set up Crowd's token store to use in-memory storage rather than database storage, so as to reduce the volume of DB queries issued by Crowd.
2011-06-01 06:34:04,780 http-4990-7 INFO [sal.core.upgrade.PluginUpgrader] Plugin com.atlassian.studio.crowd.plugin upgrade completed. Current version is: 9
2011-06-01 06:34:04,780 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@71dbf1e4
2011-06-01 06:34:04,780 http-4990-7 INFO [sal.core.upgrade.PluginUpgrader] Plugin: com.atlassian.notifier.crowd, current version: 2, highest upgrade task found: 2.
2011-06-01 06:34:04,780 http-4990-7 DEBUG [org.hibernate.transaction.JDBCTransaction] commit
2011-06-01 06:34:04,781 http-4990-7 DEBUG [org.hibernate.SQL] insert into cwd_group (group_name, lower_group_name, active, is_local, created_date, updated_date, description, group_type, directory_id, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.StringType] binding '_licensed-bamboo' to parameter: 1
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.StringType] binding '_licensed-bamboo' to parameter: 2
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.TrueFalseType] binding 'true' to parameter: 3
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.TrueFalseType] binding 'false' to parameter: 4
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.TimestampType] binding '2011-06-01 06:34:04' to parameter: 5
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.TimestampType] binding '2011-06-01 06:34:04' to parameter: 6
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.StringType] binding null to parameter: 7
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.LongType] binding '294914' to parameter: 9
2011-06-01 06:34:04,781 http-4990-7 TRACE [org.hibernate.type.LongType] binding '589828' to parameter: 10
2011-06-01 06:34:04,782 http-4990-7 DEBUG [org.hibernate.SQL] insert into cwd_app_dir_group_mapping (app_dir_mapping_id, application_id, directory_id, group_name, id) values (?, ?, ?, ?, ?)
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '327685' to parameter: 1
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '360451' to parameter: 2
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '294914' to parameter: 3
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.StringType] binding '_licensed-confluence' to parameter: 4
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '622593' to parameter: 5
2011-06-01 06:34:04,782 http-4990-7 DEBUG [org.hibernate.SQL] insert into cwd_app_dir_group_mapping (app_dir_mapping_id, application_id, directory_id, group_name, id) values (?, ?, ?, ?, ?)
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '327687' to parameter: 1
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '360453' to parameter: 2
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '294914' to parameter: 3
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.StringType] binding '_licensed-fecru' to parameter: 4
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '622594' to parameter: 5
2011-06-01 06:34:04,782 http-4990-7 DEBUG [org.hibernate.SQL] insert into cwd_app_dir_group_mapping (app_dir_mapping_id, application_id, directory_id, group_name, id) values (?, ?, ?, ?, ?)
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '327684' to parameter: 1
2011-06-01 06:34:04,782 http-4990-7 TRACE [org.hibernate.type.LongType] binding '360450' to parameter: 2
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.LongType] binding '294914' to parameter: 3
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding '_licensed-bamboo' to parameter: 4
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.LongType] binding '622595' to parameter: 5
2011-06-01 06:34:04,783 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f4a66f31
2011-06-01 06:34:04,783 http-4990-7 DEBUG [org.hibernate.SQL] update cwd_property set property_value=? where property_key=? and property_name=?
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding '9' to parameter: 1
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'plugin.null' to parameter: 2
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'com.atlassian.studio.crowd.plugin:build' to parameter: 3
2011-06-01 06:34:04,783 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@c785b199
2011-06-01 06:34:04,783 http-4990-7 DEBUG [org.hibernate.SQL] update cwd_property set property_value=? where property_key=? and property_name=?
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'false' to parameter: 1
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'crowd' to parameter: 2
2011-06-01 06:34:04,783 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'database.token.storage.enabled' to parameter: 3
2011-06-01 06:34:04,783 http-4990-7 DEBUG [org.hibernate.SQL] update cwd_token set directory_id=?, entity_name=?, random_number=?, identifier_hash=?, random_hash=?, created_date=?, last_accessed_date=? where id=?
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.LongType] binding '-1' to parameter: 1
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'crucible' to parameter: 2
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.LongType] binding '1585645689265167973' to parameter: 3
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'k0lQNVv7bIPgNmw7O9q8vA00' to parameter: 4
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.StringType] binding 'k2CyhyEI8vWhuj7gUxJvyw00' to parameter: 5
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.TimestampType] binding '2011-06-01 06:34:03' to parameter: 6
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.TimestampType] binding '2011-06-01 06:34:04' to parameter: 7
2011-06-01 06:34:04,784 http-4990-7 TRACE [org.hibernate.type.LongType] binding '458754' to parameter: 8
2011-06-01 06:34:04,784 http-4990-7 ERROR [hibernate.event.def.AbstractFlushingEventListener] Could not synchronize database state with session
2011-06-01 06:34:04,786 http-4990-7 DEBUG [org.hibernate.transaction.JDBCTransaction] rollback
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.transaction.JDBCTransaction] re-enabling autocommit
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.transaction.JDBCTransaction] rolled back JDBC Connection
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f4a66f31
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f4a66f31
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f4a66f31
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@b93d1e53
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@306583c2
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@421bc689
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@b9442bf8
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@25a7e860
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@c0c18b3c
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@d5ca9e0
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f13bac8a
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@686411f9
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@ece33c00
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@640ba16f
2011-06-01 06:34:04,788 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@5da67697
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@ecf5c05f
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@5b32f42e
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@641e25ce
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@59608a6c
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@75ab9554
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@cfc48812
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@fded6148
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@40b1baa3
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@eeafc9b3
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@a2dd25c9
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@f4a66f31
2011-06-01 06:34:04,789 http-4990-7 DEBUG [org.hibernate.cache.EhCache] key: com.atlassian.crowd.model.property.Property#com.atlassian.crowd.model.property.PropertyId@c785b199
2011-06-01 06:34:04,791 http-4990-7 ERROR [[Catalina].[localhost].[/crowd].[servlet-module-container-servlet]] Servlet.service() for servlet servlet-module-container-servlet threw exception
2011-06-01 06:34:04,793 http-4990-7 ERROR [500ErrorPage] Exception caught in 500 page Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
	at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:672)
	at org.springframework.orm.hibernate3.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:789)
	at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:663)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:732)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:701)
	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
	at com.atlassian.sal.spring.component.SpringHostContextAccessor.doInTransaction(SpringHostContextAccessor.java:82)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.atlassian.plugin.osgi.hostcomponents.impl.DefaultComponentRegistrar$ContextClassLoaderSettingInvocationHandler.invoke(DefaultComponentRegistrar.java:129)
	at $Proxy38.doInTransaction(Unknown Source)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:154)
	at $Proxy38.doInTransaction(Unknown Source)
	at com.atlassian.sal.core.transaction.HostContextTransactionTemplate.execute(HostContextTransactionTemplate.java:21)
	at com.atlassian.sal.core.upgrade.DefaultPluginUpgradeManager.upgrade(DefaultPluginUpgradeManager.java:107)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
	at org.springframework.osgi.service.importer.support.internal.aop.ServiceInvoker.doInvoke(ServiceInvoker.java:58)
	at org.springframework.osgi.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:62)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.osgi.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:56)
	at org.springframework.osgi.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:39)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.osgi.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:59)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at $Proxy153.upgrade(Unknown Source)
	at com.atlassian.studio.crowd.servlet.UpgradeServlet.doPost(UpgradeServlet.java:37)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at com.atlassian.plugin.servlet.DelegatingPluginServlet.service(DelegatingPluginServlet.java:42)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at com.atlassian.plugin.servlet.ServletModuleContainerServlet.service(ServletModuleContainerServlet.java:52)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:378)
	at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
	at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter.doFilterHttp(SecurityContextHolderAwareRequestFilter.java:91)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.ui.AbstractProcessingFilter.doFilterHttp(AbstractProcessingFilter.java:277)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.ui.logout.LogoutFilter.doFilterHttp(LogoutFilter.java:89)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
	at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
	at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:390)
	at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:175)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:236)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
	at com.atlassian.crowd.console.filter.CrowdDelegatingFilterProxy.doFilter(CrowdDelegatingFilterProxy.java:38)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:198)
	at com.atlassian.crowd.console.filter.CrowdOpenSessionInViewFilter.doFilterInternal(CrowdOpenSessionInViewFilter.java:26)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.crowd.plugin.web.filter.RequestCacheThreadLocalFilter.doFilter(RequestCacheThreadLocalFilter.java:31)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
	at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.core.filters.cache.AbstractCachingFilter.doFilter(AbstractCachingFilter.java:33)
	at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.atlassian.core.filters.encoding.AbstractEncodingFilter.doFilter(AbstractEncodingFilter.java:41)
	at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
	at java.lang.Thread.run(Thread.java:619)
Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
	at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:61)
	at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:46)
	at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:24)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2403)
	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2307)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2607)
	at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:92)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:142)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
	at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
	at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
	at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
	at org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:655)
	... 123 more

This is taken from the GApps SimpleTest Crowd log from build JST-JST-303, at line ~184341. We have not been able to re-create the failure outside of the build.

All upgrade tasks operate within a single transaction, as dictated by SAL's DefaultPluginUpgradeManager. Note the delete from cwd_token at the very top, before the commit, and the subsequent update cwd_token just before the failure. The logs suggest that the delete from cwd_token happens immediately, before the transaction is committed - even though the delete is on an upgrade tasks's codepath, and appears to use the same hibernate session as other upgrade task operations. The update to cwd_token happens later, resulting in the StaleStateException.

The origin of the update cwd_token statement is currently unclear. It could be caused by another upgrade task, but could also be a direct consequence of the HTTP request into the upgrade servlet. An interesting experiment would be to implement a dummy upgrade task that explicitly updates the cwd_token table and then switches to the in-memory token store, and see whether the db operations are still mis-ordered in that case.

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Robin Fernandes (go/robinleave) (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 02/Jun/2011 8:13 AM

Updated:: 24/Oct/2018 5:29 AM

Resolved:: 12/Oct/2017 12:36 PM