New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
could not flush state image Log corrupted - restart JVM #100
Comments
This is strange. Did you try with 5.0.3? |
Thank you for your reply. We'll try 5.0.3, but we don't know in which condition this issue will happen. |
Me neither, it's not a common issue. You mean it does not repeat then? |
Yes, not repeat now. Our project is running for several months, this issue happened for first time. |
OK it probably means some transient / temporary disk IO failure then. |
We have two test environment, and two web server, they have different disks. But the issue happened in two server almost at the same time. |
the same question as #98,I tried 5.0.3 ,the problem not solved yet!any suggestion? |
This is how it is possible to reproduce the problem in Spring Boot env:
Maybe step 1 is not necessary. I agree that calling "future.cancel(true)" is a bit "cruel" but... why it should completely break consistency of JTA log. By the way, in JavaEE (JBoss 7.1 with its default JTA manager) it works just fine and transaction is rollbacked after "future.cancel(true)" is called. |
Thanks, if you can supply a maven sample project then we can have a look. |
This is the maven sample project to reproduce the issue: https://github.com/NarimanAB/atomikos.git I think the problem is that in my test I catch InterruptedException and restore the thread state. I do it to emulate long running, not responding processes (as an example a long running DB operation). Without interrupted state restore Atomikos correctly handles exception, but with a thread interrupted state restored the whole JTA log becomes corrupted. |
Thanks - we'll have a look |
FWIW, I can see "Log corrupted - restart JVM" as well Atomikos 5.0.8 / Spring Boot 2.4.2 (on Kubernetes with 3 pods in a specific service) Seems to be some kind of cyclic cleanup job that is running there - the message shows up every 120secs - which corresponds to the set transaction time-out ( com.atomikos.icatch.default_jta_timeout=120000 ). When reducing the timeout to 60secs, the log has an interval of 60secs as well. java.lang.Thread.run(Thread.java:834) |
Thanks for the feedback @kschroiff - are you also doing threading and canceling their work? |
@GuyPardon In the meantime, I found the issue - see: Even so, it feels strange that this results in a corrupted log. |
We merely assume the log is corrupted. After checking the code I think we can be more optimistic - with a few minor changes. I used @NarimanAB 's test suite to diagnose. |
I meet a similar problem with yours as well @kschroiff |
I meet a similar problem with yours as well |
I meet the same problem when I use transactionTemplate.execute(...). Whenever an exception ocurrs in execute function, the issue well happen, and it keeps retrying. |
We use spring-boot 2.0.3 and atomikos 4.0.6 in our project.
2019-11-15 09:09:06,329 [WebContainer : 7197dfc6c93a4953a1bfe48b08d71626-f8ffdbd48--4912-T:2ae0d2f6-e9ae-4817-8ea3-c86a53fddf61] WARN CoordinatorStateHandler:40 - Error in committing: could not flush state image Log corrupted - restart JVM com.atomikos.recovery.LogReadException - recovery will clean up in the background
java.lang.IllegalStateException: could not flush state image Log corrupted - restart JVM com.atomikos.recovery.LogReadException
at com.atomikos.persistence.imp.StateRecoveryManagerImp.preEnter(StateRecoveryManagerImp.java:54) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.finitestates.FSMImp.notifyListeners(FSMImp.java:164) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.finitestates.FSMImp.setState(FSMImp.java:251) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CoordinatorImp.setState(CoordinatorImp.java:312) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CoordinatorStateHandler.commitFromWithinCallback(CoordinatorStateHandler.java:346) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.ActiveStateHandler$6.doCommit(ActiveStateHandler.java:268) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CoordinatorStateHandler.commitWithAfterCompletionNotification(CoordinatorStateHandler.java:581) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.ActiveStateHandler.commit(ActiveStateHandler.java:263) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CoordinatorImp.commit(CoordinatorImp.java:548) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CoordinatorImp.terminate(CoordinatorImp.java:685) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.imp.CompositeTransactionImp.commit(CompositeTransactionImp.java:282) [transactions-4.0.6.jar!/:?]
at com.atomikos.icatch.jta.TransactionImp.commit(TransactionImp.java:172) [transactions-jta-4.0.6.jar!/:?]
at com.atomikos.icatch.jta.TransactionManagerImp.commit(TransactionManagerImp.java:414) [transactions-jta-4.0.6.jar!/:?]
at com.atomikos.icatch.jta.UserTransactionImp.commit(UserTransactionImp.java:86) [transactions-jta-4.0.6.jar!/:?]
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1034) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:714) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:532) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:304) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98) [spring-tx-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at com.huawei.it.jalor5.security.service.impl.internal.SecurityInterceptor.invoke(SecurityInterceptor.java:100) [jalor-authorization-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at com.huawei.it.jalor5.security.service.impl.internal.SecurityInterceptor.invoke(SecurityInterceptor.java:100) [jalor-authorization-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) [spring-aop-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at com.huawei.it.hr.bonus.reimbursement.service.impl.PersonalReimbursementService$$EnhancerBySpringCGLIB$$8ddb519b.queryPersonalReimbursement() [classes!/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_201]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_201]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_201]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_201]
at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:192) [cxf-rt-frontend-jaxrs-3.2.5.jar!/:3.2.5]
at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:103) [cxf-rt-frontend-jaxrs-3.2.5.jar!/:3.2.5]
at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-core-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:216) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:301) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:225) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:276) [cxf-rt-transports-http-3.2.5.jar!/:3.2.5]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-embed-websocket-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.hr.bonus.filters.BonusUserFilter.doFilter(BonusUserFilter.java:60) [classes!/:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.jalor5.web.support.filter.AdditionalFilter.doFilter(AdditionalFilter.java:59) [jalor-web-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.celon.bpm.filter.BpmRequestContextFilter.doFilter(BpmRequestContextFilter.java:56) [bpm-external-sdk-jalor-0.0.1.beta.RELEASE.jar!/:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.sso.filter.SsoFilterPub.doFilter(SsoFilterPub.java:175) [sso-login-axis-hae-0.1.jar!/:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.jalor5.security.filter.JwtRequestFilter.doFilter(JwtRequestFilter.java:278) [jalor-auth-jwt-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.jalor5.web.support.filter.RequestContextFilter.doFilter(RequestContextFilter.java:73) [jalor-web-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.jalor5.web.support.filter.CharaterEncodingFilter.doFilter(CharaterEncodingFilter.java:29) [jalor-web-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at com.huawei.it.usf.tracer.handler.server.TracerServerFilter.doFilter(TracerServerFilter.java:70) [jalor-tracer-6.5.3.RELEASE.jar!/:6.5.3.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.31.jar!/:8.5.31]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: com.atomikos.recovery.LogReadException: Log corrupted - restart JVM
at com.atomikos.recovery.imp.CachedRepository.assertNotCorrupted(CachedRepository.java:138) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.recovery.imp.CachedRepository.get(CachedRepository.java:132) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.recovery.imp.OltpLogImp.assertEntryIsAllowedInCurrentState(OltpLogImp.java:35) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.recovery.imp.OltpLogImp.write(OltpLogImp.java:30) ~[transactions-4.0.6.jar!/:?]
at com.atomikos.persistence.imp.StateRecoveryManagerImp.preEnter(StateRecoveryManagerImp.java:51) ~[transactions-4.0.6.jar!/:?]
... 110 more
2019-11-15 09:09:06,332 [WebContainer : 7197dfc6c93a4953a1bfe48b08d71626-f8ffdbd48-y00254986-4912-T:2ae0d2f6-e9ae-4817-8ea3-c86a53fddf61] DEBUG ExceptionHandler:179 - No converter found.Jalor could not convert exception:org.springframework.transaction.UnexpectedRollbackException
2019-11-15 09:09:06,333 [WebContainer : 7197dfc6c93a4953a1bfe48b08d71626-f8ffdbd48-y00254986-4912-T:2ae0d2f6-e9ae-4817-8ea3-c86a53fddf61] ERROR ExceptionHandler:195 - Code:[null],User:[y00254986],[Error:JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is javax.transaction.RollbackException: Error in committing: could not flush state image Log corrupted - restart JVM
The text was updated successfully, but these errors were encountered: