[Deploying Sakai] Cascade failure with 'load.bundles.from.db=true'
Jean-Francois Leveque
jean-francois.leveque at upmc.fr
Fri Sep 16 02:24:37 PDT 2011
Hi,
This is a follow-up on the slow log issue with nasty consequences.
When the requests takes too much time, it looks like it breaks more than
itself.
I first get this failure on the update :
> 2011-09-15 09:07:27,269 ERROR Timer-3 org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
> 2011-09-15 09:07:27,270 ERROR Timer-3 org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session
> org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
> at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
> at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
> at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
> at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:254)
> at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
> at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
> 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:1001)
> at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
> at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:420)
> at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
> at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:748)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.updateMessageBundleProperty(MessageBundleServiceImpl.java:272)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdateInternal(MessageBundleServiceImpl.java:193)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl$SaveOrUpdateTask.run(MessageBundleServiceImpl.java:453)
> at java.util.TimerThread.mainLoop(Timer.java:512)
> at java.util.TimerThread.run(Timer.java:462)
> Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
> at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2024)
> at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
> at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
> at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
> at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:247)
> ... 14 more
> Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)
> at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
> at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
> ... 18 more
> Exception in thread "Timer-3" org.springframework.dao.CannotAcquireLockException: Hibernate operation: Could not execute JDBC batch update; SQL [update SAKAI_MESSAGE_BUNDLE set MODULE_NAME=?, BASENAME=?, PROP_NAME=?, PROP_VALUE=?, LOCALE=?, DEFAULT_VALUE=? where ID=?]; Lock wait timeout exceeded; try restarting transaction; nested exception is java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
> at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:244)
> at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
> at org.springframework.orm.hibernate3.HibernateAccessor.convertJdbcAccessException(HibernateAccessor.java:424)
> at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:410)
> at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:424)
> at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
> at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:748)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.updateMessageBundleProperty(MessageBundleServiceImpl.java:272)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdateInternal(MessageBundleServiceImpl.java:193)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl$SaveOrUpdateTask.run(MessageBundleServiceImpl.java:453)
> at java.util.TimerThread.mainLoop(Timer.java:512)
> at java.util.TimerThread.run(Timer.java:462)
> Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
> at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2024)
> at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
> at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
> at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
> at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:247)
> at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
> at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
> 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:1001)
> at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
> at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:420)
> ... 7 more
> Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)
> at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
> at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
> at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
> ... 18 more
I then start to get ERRORs like :
> 2011-09-15 09:09:25,326 ERROR TP-Processor24 org.sakaiproject.portal.util.ErrorReporter - Failed to generate request display
> java.lang.IllegalStateException: Timer already cancelled.
> at java.util.Timer.sched(Timer.java:354)
> at java.util.Timer.schedule(Timer.java:170)
> at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdate(MessageBundleServiceImpl.java:145)
> at sun.reflect.GeneratedMethodAccessor427.invoke(Unknown Source)
> 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.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
> at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
> at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> at $Proxy135.saveOrUpdate(Unknown Source)
> at org.sakaiproject.util.DbResourceBundle.indexResourceBundle(DbResourceBundle.java:140)
> at org.sakaiproject.util.ResourceLoader.loadBundleFromDb(ResourceLoader.java:635)
> at org.sakaiproject.util.ResourceLoader.loadBundle(ResourceLoader.java:588)
> at org.sakaiproject.util.ResourceLoader.getBundleFromDb(ResourceLoader.java:556)
> at org.sakaiproject.util.ResourceLoader.getBundle(ResourceLoader.java:529)
> at org.sakaiproject.util.ResourceLoader.getString(ResourceLoader.java:370)
> at org.sakaiproject.portal.util.ErrorReporter.requestDisplay(ErrorReporter.java:596)
> at org.sakaiproject.portal.util.ErrorReporter.report(ErrorReporter.java:417)
> at org.sakaiproject.portal.util.ErrorReporter.report(ErrorReporter.java:399)
> at org.sakaiproject.portal.charon.SkinnableCharonPortal.doThrowableError(SkinnableCharonPortal.java:379)
> at org.sakaiproject.portal.charon.SkinnableCharonPortal.doGet(SkinnableCharonPortal.java:903)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:627)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
> at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:659)
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
> at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
> at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
> at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:775)
> at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:704)
> at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:897)
> at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
> at java.lang.Thread.run(Thread.java:662)
> 2011-09-15 09:09:25,337 ERROR TP-Processor24 org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/portal].[sakai.portal.charon] - "Servlet.service()" pour la servlet sakai.portal.charon a généré une exception
And they keep coming until Tomcat is restarted.
Cheers,
J-F
--
Jean-Francois Leveque
Australe (local Sakai CLE) CTO
University Pierre and Marie Curie
France
More information about the production
mailing list