search

datacite / mds

The DataCite Metadata Store (MDS)
https://mds.datacite.org
Apache License 2.0
25 stars 16 forks source link

MySQL Lock timeout exception stops the whole application #299

Closed koelnconcert closed 6 years ago

koelnconcert commented 9 years ago

Shortly after a mysql "Lock wait timeout exceeded" occurs, the application stops to accepts any incoming connections. It will not repair itself.

relevant log with stacktrace:

2015-04-23 04:56:31,108 [http-bio-8080-exec-16] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,108 [http-bio-8080-exec-16] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,108 [http-bio-8080-exec-1] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,108 [http-bio-8080-exec-1] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,109 [http-bio-8080-exec-10] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,109 [http-bio-8080-exec-10] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,109 [http-bio-8080-exec-17] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,109 [http-bio-8080-exec-17] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,110 [http-bio-8080-exec-13] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,110 [http-bio-8080-exec-13] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,110 [http-bio-8080-exec-14] WARN  org.hibernate.util.JDBCExceptionReporter - SQL Error: 1205, SQLState: 41000
2015-04-23 04:56:31,110 [http-bio-8080-exec-14] ERROR org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2015-04-23 04:56:31,111 [http-bio-8080-exec-1] DEBUG org.datacite.mds.web.api.ApiHandlerExceptionResolver - Resolving exception from handler [public org.springframework.http.ResponseEntity<java.lang.String> org.datacite.mds.web.api.controller.DoiApiController.post(java.lang.String,java.lang.Boolean,javax.servlet.http.HttpServletRequest) throws javax.validation.ValidationException,org.datacite.mds.service.HandleException,org.datacite.mds.service.SecurityException,org.datacite.mds.web.api.NotFoundException,java.io.IOException]: org.springframework.orm.jpa.JpaSystemException: org.hibernate.exception.GenericJDBCException: could not execute update query; nested exception is javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute update query
2015-04-23 04:56:31,111 [http-bio-8080-exec-1] DEBUG org.datacite.mds.web.api.ApiHandlerExceptionResolver - handling exception: org.springframework.orm.jpa.JpaSystemException: org.hibernate.exception.GenericJDBCException: could not execute update query; nested exception is javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute update query
    at org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:415)
    at org.springframework.orm.jpa.aspectj.JpaExceptionTranslatorAspect.ajc$afterThrowing$org_springframework_orm_jpa_aspectj_JpaExceptionTranslatorAspect$1$18a1ac9(JpaExceptionTranslatorAspect.aj:37)
    at org.datacite.mds.domain.Datacentre.incQuotaUsed_aroundBody0(Datacentre.java:186)
    at org.datacite.mds.domain.Datacentre$AjcClosure1.run(Datacentre.java:1)
    at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96cproceed(AbstractTransactionAspect.aj:66)
    at org.springframework.transaction.aspectj.AbstractTransactionAspect$AbstractTransactionAspect$1.proceedWithInvocation(AbstractTransactionAspect.aj:72)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
    at org.springframework.transaction.aspectj.AbstractTransactionAspect.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96c(AbstractTransactionAspect.aj:70)
    at org.datacite.mds.domain.Datacentre.incQuotaUsed(Datacentre.java:184)
    at org.datacite.mds.service.impl.DoiServiceImpl.createOrUpdate(DoiServiceImpl.java:55)
    at org.datacite.mds.web.api.controller.DoiApiController.createOrUpdate(DoiApiController.java:163)
    at org.datacite.mds.web.api.controller.DoiApiController.postDataset(DoiApiController.java:95)
    at org.datacite.mds.web.api.controller.DoiApiController.post(DoiApiController.java:103)
    at sun.reflect.GeneratedMethodAccessor58.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:777)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:706)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:943)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:877)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:868)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:201)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:344)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:261)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.springframework.orm.jpa.support.OpenEntityManagerInViewFilter.doFilterInternal(OpenEntityManagerInViewFilter.java:176)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not execute update query
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1389)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1317)
    at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1399)
    at org.hibernate.ejb.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:108)
    ... 71 more
Caused by: org.hibernate.exception.GenericJDBCException: could not execute update query
    at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:110)
    at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:423)
    at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283)
    at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1288)
    at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117)
    at org.hibernate.ejb.QueryImpl.internalExecuteUpdate(QueryImpl.java:188)
    at org.hibernate.ejb.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:99)
    ... 71 more
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:996)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3887)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3823)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2530)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1907)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2141)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2077)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2062)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
    at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:101)
    ... 77 more
koelnconcert commented 9 years ago

Looks like a race condition by the incQuotaUsed sql query, whene if there are too many parallel minting request by the same datacentre.