I have a simple function in MessageController that is called by the mail compose page every 1 second using ajax call. It is a simple function to periodically save the message draft so that the message written by the user is not lost if something happens like crash or accidental redirect to other pages.
The method is as follows
def saveDraft(){
if (request.xhr) {
def event_only = params['event_only'].toBoolean()
def event_id = params['event_id'].toLong()
def event
if(event_only) {
event = CompositeEvent.get(event_id)
}
EventEmailDraft.withTransaction {
def user = User.get(springSecurityService.principal.id)
def draft
if(event_only){
draft = EventEmailDraft.findByEvent(event)
}
else{
draft = MassEmailDraft.findByUser(user)
}
if(draft) {
draft.subject = params['subject']
draft.body = params['body']
draft.emails = params['add_emails']
draft.save()
}
render "ok"
}
}
else{
render "invalid"
}
}
In the logs once in a while I am seeing this error message. The pointed line for the error is Line 93 which is
EventEmailDraft.withTransaction {
I don't know how to mitigate it since I cannot recreate it every time. It only appears sometimes in the logs. What can I try next?
I am using Grails 4.0.10 app.
2023-08-04 06:14:53.790 ERROR --- [io-8080-exec-12] StackTrace : Full Stack Trace:
org.springframework.orm.hibernate5.HibernateOptimisticLockingFailureException: Object of class [com.company.EventEmailDraft] with identifier [334]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.company.EventEmailDraft#334]
at org.springframework.orm.hibernate5.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:284)
at org.springframework.orm.hibernate5.HibernateTransactionManager.convertHibernateAccessException(HibernateTransactionManager.java:802)
at org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:638)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)
at grails.gorm.transactions.GrailsTransactionTemplate.execute(GrailsTransactionTemplate.groovy:91)
at org.grails.datastore.gorm.GormStaticApi.withTransaction(GormStaticApi.groovy:1014)
at org.grails.datastore.gorm.GormStaticApi.withTransaction(GormStaticApi.groovy:877)
at org.grails.datastore.gorm.GormEntity$Trait$Helper.withTransaction(GormEntity.groovy:941)
at org.grails.datastore.gorm.GormEntity$Trait$Helper$withTransaction$2.call(Unknown Source)
at com.company.EventEmailDraft.withTransaction(EventEmailDraft.groovy)
at com.company.EventEmailDraft$withTransaction$0.call(Unknown Source)
at com.company.MessageController.saveDraft(MessageController.groovy:93)
at org.grails.core.DefaultGrailsControllerClass$MethodHandleInvoker.invoke(DefaultGrailsControllerClass.java:223)
at org.grails.core.DefaultGrailsControllerClass.invoke(DefaultGrailsControllerClass.java:188)
at org.grails.web.mapping.mvc.UrlMappingsInfoHandlerAdapter.handle(UrlMappingsInfoHandlerAdapter.groovy:90)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:652)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
at org.springframework.security.web.authentication.switchuser.SwitchUserFilter.doFilter(SwitchUserFilter.java:200)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119)
at grails.plugin.springsecurity.web.UpdateRequestContextHolderExceptionTranslationFilter.doFilter(UpdateRequestContextHolderExceptionTranslationFilter.groovy:64)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at grails.plugin.springsecurity.web.filter.GrailsAnonymousAuthenticationFilter.doFilter(GrailsAnonymousAuthenticationFilter.groovy:54)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:158)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
...
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:747)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.company.EventEmailDraft#334]
at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:2604)
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3448)
at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3311)
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3723)
at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:201)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604)
at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)
at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:684)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:348)
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:102)
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1360)
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:451)
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3210)
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2378)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
at org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:626)
... 99 common frames omitted
I think it might be a multi-threading issue where 2 threads are trying to run this method at the same time. Because you have such a small period of 1 second if one thread lags a little bit it could cause the browser to run 2 saves at the same time.
If you get into a situation where the 1st thread loads the email, and the 2nd thread loads the email, then the 1st thread saves it. That will cause the 2nd thread to blow up with this. Some very careful logging statements would help you identify if you had that situation. Add logging statements after the email is loaded, and after the save. Then if you have your log4j configuration setup to log the thread name you can check the logs after reproducing it and see if you see 2 threads running at the same time.
If you have multiple servers running you might have to check timestamps to know if they are running at the same time.
These suggestions aren't mutually exclusive either. So you might choose to implement #2 and #4. #2 recovers for when two threads try to save the object simultaneous, and #4 to make that possibility less likely.