multipleExecutions Error

#563

Issue Type: Bug
Rundeck version: 1.4.2-1

Issue:

When running a job concurrently with different options one always fails with a 500 and the error below in services.log. We tried changing the amount of threads also the strategy. All resulted in the same outcome. We are also using ldap authentication. Attached is the job.

$ xargs -P2 -n 1 wget -x -nv --load-cookies cookies.txt  < url.txt 
2012-04-25 15:03:51 URL:http://rundeck.XXXX.net/api/1/job/90569740-5b52-4737-80a6-d4de8d354604/run?argString=-host+as-d.XXX.net+-runmode+author [581] -> "rundeck.XXX.net/api/1/job/90569740-5b52-4737-80a6-d4de8d354604/run?argString=-host+as-d.XXX.net+-runmode+author" [1]
http://rundeck.XXX.net/api/1/job/90569740-5b52-4737-80a6-d4de8d354604/run?argString=-host+w-d.XXX.net+-runmode+publish:
2012-04-25 15:03:51 ERROR 500: Internal Server Error.

..rundeck/service.log

INFO  ExecutionService: updated scheduled Execution
ERROR PatchedDefaultFlushEventListener: Could not synchronize database state with session
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [ScheduledExecution#32]
    at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1792)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2435)
    at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2335)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2635)
    at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
    at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
    at org.codehaus.groovy.grails.orm.hibernate.events.PatchedDefaultFlushEventListener.performExecutions(PatchedDefaultFlushEventListener.java:46)
    at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
    at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
    at org.springframework.orm.hibernate3.HibernateTemplate$28.doInHibernate(HibernateTemplate.java:883)
    at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
    at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
    at org.springframework.orm.hibernate3.HibernateTemplate.flush(HibernateTemplate.java:881)
    at org.codehaus.groovy.grails.orm.hibernate.metaclass.SavePersistentMethod$1.doInHibernate(SavePersistentMethod.java:58)
    at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406)
    at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:339)
    at org.codehaus.groovy.grails.orm.hibernate.metaclass.SavePersistentMethod.performSave(SavePersistentMethod.java:53)
    at org.codehaus.groovy.grails.orm.hibernate.metaclass.AbstractSavePersistentMethod.doInvokeInternal(AbstractSavePersistentMethod.java:179)
    at org.codehaus.groovy.grails.orm.hibernate.metaclass.AbstractDynamicPersistentMethod.invoke(AbstractDynamicPersistentMethod.java:59)
    at sun.reflect.GeneratedMethodAccessor326.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSite.invoke(PojoMetaMethodSite.java:188)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:40)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:54)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:132)
    at org.codehaus.groovy.grails.plugins.orm.hibernate.HibernatePluginSupport$_addBasicPersistenceMethods_closure71.doCall(HibernatePluginSupport.groovy:806)
    at sun.reflect.GeneratedMethodAccessor749.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaMethod.invoke(ClosureMetaMethod.java:80)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoMetaMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:307)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.call(PogoMetaMethodSite.java:63)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
    at ExecutionService.createExecution(ExecutionService.groovy:1015)
    at ExecutionService$$FastClassByCGLIB$$38316c9d.invoke(<generated>)
    at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149)
    at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:688)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:621)
    at ExecutionService$$EnhancerByCGLIB$$bc4d08a7.createExecution(<generated>)
    at ExecutionService$createExecution$0.call(Unknown Source)
    at ScheduledExecutionController.executeScheduledExecution(ScheduledExecutionController.groovy:2759)
    at sun.reflect.GeneratedMethodAccessor1005.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1058)
    at groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1070)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:886)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1003)
    at groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1070)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:886)
    at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:66)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:161)
    at ScheduledExecutionController$_closure41.doCall(ScheduledExecutionController.groovy:3031)
    at sun.reflect.GeneratedMethodAccessor1004.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSite.invoke(PogoMetaMethodSite.java:225)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:51)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:149)
    at ScheduledExecutionController$_closure41.doCall(ScheduledExecutionController.groovy)
    at sun.reflect.GeneratedMethodAccessor1003.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1058)
    at groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1070)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:886)
    at groovy.lang.Closure.call(Closure.java:282)
    at groovy.lang.Closure.call(Closure.java:277)
    at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleAction(SimpleGrailsControllerHelper.java:368)
    at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.executeAction(SimpleGrailsControllerHelper.java:232)
    at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleURI(SimpleGrailsControllerHelper.java:190)
    at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsControllerHelper.handleURI(SimpleGrailsControllerHelper.java:129)
    at org.codehaus.groovy.grails.web.servlet.mvc.SimpleGrailsController.handleRequest(SimpleGrailsController.java:73)
    at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
    at org.codehaus.groovy.grails.web.servlet.GrailsDispatcherServlet.doDispatch(GrailsDispatcherServlet.java:292)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:644)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:549)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:70)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:70)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:70)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
    at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:327)
    at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:126)
    at org.codehaus.groovy.grails.web.util.WebUtils.forwardRequestForUrlMappingInfo(WebUtils.java:298)
    at org.codehaus.groovy.grails.web.util.WebUtils.forwardRequestForUrlMappingInfo(WebUtils.java:264)
    at org.codehaus.groovy.grails.web.util.WebUtils.forwardRequestForUrlMappingInfo(WebUtils.java:255)
    at org.codehaus.groovy.grails.web.mapping.filter.UrlMappingsFilter.doFilterInternal(UrlMappingsFilter.java:183)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.codehaus.groovy.grails.web.sitemesh.GrailsPageFilter.obtainContent(GrailsPageFilter.java:245)
    at org.codehaus.groovy.grails.web.sitemesh.GrailsPageFilter.doFilter(GrailsPageFilter.java:134)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.codehaus.groovy.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:69)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.codehaus.groovy.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:69)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
    at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:536)
    at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:915)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:539)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:405)
    at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
ERROR GrailsExceptionResolver: Exception occurred when processing request: [GET] /api/1/job/90569740-5b52-4737-80a6-d4de8d354604/run
Stacktrace follows:
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [ScheduledExecution#32]
    at ExecutionService.createExecution(ExecutionService.groovy:1015)
    at ExecutionService$$FastClassByCGLIB$$38316c9d.invoke(<generated>)
    at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149)
    at ExecutionService$$EnhancerByCGLIB$$bc4d08a7.createExecution(<generated>)
    at ExecutionService$createExecution$0.call(Unknown Source)
    at ScheduledExecutionController.executeScheduledExecution(ScheduledExecutionController.groovy:2759)
    at ScheduledExecutionController$_closure41.doCall(ScheduledExecutionController.groovy:3031)
    at ScheduledExecutionController$_closure41.doCall(ScheduledExecutionController.groovy)
INFO  ScheduledExecutionService: scheduling immediate job run: TEMP:lcasey:32:506
INFO  ExecutionService: Execution successful: 506
INFO  ExecutionService: updated scheduled Execution

Reproduce:

Create a job and run it concurrently passing different options.

cache_flush.xml 1.51 KB

Reported by Luiz Casey · April 25th, 2012 @ 01:50 PM

Activity

Luiz Casey
I guess this really isn't a multiple execution issue but more of a concurrent running issue. The job runs fine when ran in series while the other is still running.

April 26th, 2012 @ 05:58 AM
Greg Schueler
- Tag set to bug, database, jobs, locking
if you use the (default) hsqldb file-based storage, which doesn't support "pessimistic" locking, this can occur.

I think that using a relational db, or H2, will not have this issue because they do support pessimistic locking, but I haven't verified this.

April 26th, 2012 @ 02:19 PM
Luiz Casey
Not sure if this would be a separate ticket or not but what about upgrading to grails 2.0+ which then uses by default H2 now vs hsqldb. Then maybe can use serialized locking vs file.

May 4th, 2012 @ 07:42 AM
Greg Schueler
Yes, we can add Grails 2.0 upgrade as a separate ticket. Setting h2 as the default db is also doable without upgrading grails.

I did some testing with h2 on the current codebase, but it didn't seem to help with the locking issue, so I think we have to investigate it a bit further.

May 7th, 2012 @ 10:32 AM
Luiz Casey
I played around with this a bit and it seemed to have worked.

1) Installed and started up h2db
2) Copied h2*.jar to $RDECK_BASE/server/lib
3) dataSource.url = jdbc:h2:/tmp/test;FILE_LOCK=SERIALIZED
4) rundeck.v14.rdbsupport=true
5) started up rundeck.

Parallel jobs worked fine coming from Jenkins which was my initial issue.

May 11th, 2012 @ 08:48 AM
Greg Schueler
- State changed from new to needs_verification
(from [488b2bc4dec17e918788d20ecb50105b17ef096a]) Fix conflict due to multiple executions

Remove need to update ScheduledExecution when creating new Executions.
Handle locking conflicts on execution completion when updating
ScheduledExecution stats by retrying.
Update notifications to handle case when hibernate session has closed.
Update tests.

[#563 multipleExecutions Error state:needs_verification] https://github.com/dtolabs/rundeck/commit/488b2bc4dec17e918788d20ec...

May 11th, 2012 @ 04:47 PM
Greg Schueler
- Milestone set to Rundeck 1.4.3
- Milestone order changed from 131 to 0
I committed a fix for this issue that works for optimistic or pessimistic locking (hsqldb as well as h2).

I removed an unnecessary data dependency (a link from executions to the jobs they belong to), and then added some retry logic for updating the Job stats when multiple executions finish at the same time.

May 11th, 2012 @ 04:49 PM
Greg Schueler
- State changed from needs_verification to resolved
June 20th, 2012 @ 01:54 PM

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.