servicecomb-pack icon indicating copy to clipboard operation
servicecomb-pack copied to clipboard

Published 20 hours ago • verified publisher icon apache

超時場景下 Failed to process grpc coordinate command

Open whitemeng opened this issue 6 years ago • 14 comments

image 超時場景下，console log 會噴出下圖錯誤訊息，想請教是什麼原因造成的，感謝 image image

omega-spring-starter & omega-transport-resttemplate 版本皆為 0.5.0 springboot 版本是 2.1.9.RELEASE

alpha-server console log image

whitemeng avatar Nov 07 '19 06:11 whitemeng

你的cancel方法中sleep了10秒，但是你在 @Compensable 中声明了cancel方法5秒的调用超时

coolbeevip avatar Nov 07 '19 09:11 coolbeevip

你的cancel方法中sleep了10秒，但是你在 @Compensable 中声明了cancel方法5秒的调用超时

對不起，我不太懂您的意思，能否再詳細說明一下，感謝 !

whitemeng avatar Nov 07 '19 09:11 whitemeng

你的cancel方法中sleep了10秒，但是你在 @Compensable 中声明了cancel方法5秒的调用超时

對不起，我不太懂您的意思，能否再詳細說明一下，感謝 !

我又看了一下，也不太敢确定，你可以提供一下你自己服务端更详细的错误日志吗

coolbeevip avatar Nov 07 '19 09:11 coolbeevip

你的cancel方法中sleep了10秒，但是你在 @Compensable 中声明了cancel方法5秒的调用超时

對不起，我不太懂您的意思，能否再詳細說明一下，感謝 !

我又看了一下，也不太敢确定，你可以提供一下你自己服务端更详细的错误日志吗

serviceA 程式碼 image

serviceB 程式碼 image

測試場景: serviceB 會因為超時而執行補償呼叫 cancel()

serviceB 詳細 console log 如下

2019-11-11 13:29:52.861 DEBUG 9180 --- [nio-9001-exec-1] o.a.s.p.o.transaction.TransactionAspect : Updated context OmegaContext{globalTxId=80465bee-caf7-4083-b401-2d149b0d2010, localTxId=af4cbf20-6b08-40d5-83ec-127fc2bcca5b, alphaFeatureAkkaEnabled=false} for compensable method public java.util.List com.example.microserviceB.service.BasicService.getNames() 2019-11-11 13:29:52.867 DEBUG 9180 --- [nio-9001-exec-1] o.a.s.p.o.transaction.DefaultRecovery : Intercepting compensable method public java.util.List com.example.microserviceB.service.BasicService.getNames() with context OmegaContext{globalTxId=80465bee-caf7-4083-b401-2d149b0d2010, localTxId=af4cbf20-6b08-40d5-83ec-127fc2bcca5b, alphaFeatureAkkaEnabled=false} 2019-11-11 13:29:57.868 WARN 9180 --- [ probe] o.a.s.p.o.t.wrapper.TimeoutProb : Thread interrupted on 5001ms timeout (over 5000ms) 2019-11-11 13:29:57.878 ERROR 9180 --- [nio-9001-exec-1] o.a.s.p.o.c.g.c.LoadBalanceSenderAdapter : Retry sending event TxEndedEvent{globalTxId='80465bee-caf7-4083-b401-2d149b0d2010', localTxId='af4cbf20-6b08-40d5-83ec-127fc2bcca5b', parentTxId='80465bee-caf7-4083-b401-2d149b0d2010', compensationMethod='public java.util.List com.example.microserviceB.service.BasicService.cancel()', timeout=0, retryMethod='', retries=0, payloads=[]} due to failure

io.grpc.StatusRuntimeException: CANCELLED: Call was interrupted at io.grpc.Status.asRuntimeException(Status.java:517) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:129) ~[grpc-stub-1.14.0.jar:1.14.0] at org.apache.servicecomb.pack.contract.grpc.TxEventServiceGrpc$TxEventServiceBlockingStub.onTxEvent(TxEventServiceGrpc.java:273) ~[pack-contract-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcSagaClientMessageSender.send(GrpcSagaClientMessageSender.java:90) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender$1.apply(SagaLoadBalanceSender.java:45) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender$1.apply(SagaLoadBalanceSender.java:42) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.doGrpcSend(LoadBalanceSenderAdapter.java:54) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:42) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensableInterceptor.postIntercept(CompensableInterceptor.java:40) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.DefaultRecovery.applyTo(DefaultRecovery.java:70) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.wrapper.RecoveryPolicyTimeoutWrapper.applyTo(RecoveryPolicyTimeoutWrapper.java:111) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.AbstractRecoveryPolicy.apply(AbstractRecoveryPolicy.java:38) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.TransactionAspect.advise(TransactionAspect.java:66) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.example.microserviceB.service.BasicService$$EnhancerBySpringCGLIB$$9924eaf.getNames() ~[classes/:na] at com.example.microserviceB.controller.BasicController.names(BasicController.java:20) ~[classes/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na] Caused by: java.lang.InterruptedException: null at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[na:na] at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090) ~[na:na] at java.base/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:433) ~[na:na] at io.grpc.stub.ClientCalls$ThreadlessExecutor.waitAndDrain(ClientCalls.java:629) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:123) ~[grpc-stub-1.14.0.jar:1.14.0] ... 87 common frames omitted

2019-11-11 13:29:57.880 DEBUG 9180 --- [nio-9001-exec-1] o.a.s.p.o.transaction.TransactionAspect : Restored context back to OmegaContext{globalTxId=80465bee-caf7-4083-b401-2d149b0d2010, localTxId=80465bee-caf7-4083-b401-2d149b0d2010, alphaFeatureAkkaEnabled=false} 2019-11-11 13:29:57.892 ERROR 9180 --- [nio-9001-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.apache.servicecomb.pack.omega.transaction.OmegaException: Failed to get reconnected sender] with root cause

java.lang.InterruptedException: null at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1261) ~[na:na] at java.base/java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:317) ~[na:na] at java.base/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:453) ~[na:na] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:71) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:67) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.FastestSender.pick(FastestSender.java:39) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.pickMessageSender(LoadBalanceSenderAdapter.java:46) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:41) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensableInterceptor.onError(CompensableInterceptor.java:45) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.DefaultRecovery.applyTo(DefaultRecovery.java:74) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.wrapper.RecoveryPolicyTimeoutWrapper.applyTo(RecoveryPolicyTimeoutWrapper.java:111) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.AbstractRecoveryPolicy.apply(AbstractRecoveryPolicy.java:38) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.TransactionAspect.advise(TransactionAspect.java:66) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.example.microserviceB.service.BasicService$$EnhancerBySpringCGLIB$$9924eaf.getNames() ~[classes/:na] at com.example.microserviceB.controller.BasicController.names(BasicController.java:20) ~[classes/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]

2019-11-11 13:29:58.251 INFO 9180 --- [ault-executor-2] s.p.o.c.g.s.GrpcCompensateStreamObserver : Received compensate command, global tx id: 80465bee-caf7-4083-b401-2d149b0d2010, local tx id: af4cbf20-6b08-40d5-83ec-127fc2bcca5b, compensation method: public java.util.List com.example.microserviceB.service.BasicService.cancel() 2019-11-11 13:29:58.254 INFO 9180 --- [ault-executor-2] c.e.microserviceB.service.BasicService : B BasicService cancel() 2019-11-11 13:29:58.255 INFO 9180 --- [ault-executor-2] o.a.s.p.omega.context.CallbackContext : Callback transaction with global tx id [80465bee-caf7-4083-b401-2d149b0d2010], local tx id [af4cbf20-6b08-40d5-83ec-127fc2bcca5b] 2019-11-11 13:30:06.256 ERROR 9180 --- [ault-executor-2] o.a.s.p.o.c.g.c.ReconnectStreamObserver : Failed to process grpc coordinate command.

io.grpc.StatusRuntimeException: CANCELLED: Failed to read message. at io.grpc.Status.asRuntimeException(Status.java:526) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:420) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:684) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:403) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:459) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:546) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:467) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:531) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) ~[grpc-core-1.14.0.jar:1.14.0] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na] Caused by: org.apache.servicecomb.pack.omega.transaction.OmegaException: Failed to get reconnected sender, all alpha server is down. at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:73) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:67) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.FastestSender.pick(FastestSender.java:39) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.pickMessageSender(LoadBalanceSenderAdapter.java:46) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:41) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensationMessageHandler.onReceive(CompensationMessageHandler.java:36) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:205) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.sun.proxy.$Proxy114.onReceive(Unknown Source) ~[na:na] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:52) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:31) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:407) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:519) ~[grpc-core-1.14.0.jar:1.14.0] ... 5 common frames omitted

2019-11-11 13:30:06.259 INFO 9180 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 2019-11-11 13:30:06.271 ERROR 9180 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Failed to reconnect to alpha at 192.168.205.14:8080

io.grpc.StatusRuntimeException: UNKNOWN at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:222) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:203) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:132) ~[grpc-stub-1.14.0.jar:1.14.0] at org.apache.servicecomb.pack.contract.grpc.TxEventServiceGrpc$TxEventServiceBlockingStub.onDisconnected(TxEventServiceGrpc.java:280) ~[pack-contract-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcSagaClientMessageSender.onDisconnected(GrpcSagaClientMessageSender.java:75) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.PushBackReconnectRunnable.run(PushBackReconnectRunnable.java:52) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.PendingTaskRunner$1.run(PendingTaskRunner.java:44) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na] at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]

2019-11-11 13:30:09.272 INFO 9180 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 2019-11-11 13:30:09.279 INFO 9180 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 is successful

alpha-server console log 如下 image

whitemeng avatar Nov 11 '19 05:11 whitemeng

因为TimeoutProb检测出调用超时了，触发了InterruptedException， 但是由于这个Exception被吃到了，（RecoveryPolicyTimeoutWrapper 需要根据InterruptedException 做一些处理）导致后续处理出现问题。

2019-11-11 13:29:57.868 WARN 9180 --- [ probe] o.a.s.p.o.t.wrapper.TimeoutProb : Thread interrupted on 5001ms timeout (over 5000ms)

建议把 ServiceB 中getNames() 方法中的 catch(InterruptedException e) 的代码去掉再跑一下看看。

WillemJiang avatar Nov 11 '19 07:11 WillemJiang

@WillemJiang 但是看他最后出错的exception报的是连不上alpha server，这个是什么意思呢？当时的timeout probe是根据超时设置来调用thread.interrupt()

zhfeng avatar Nov 11 '19 07:11 zhfeng

InterruptedException 这个异常是因为 @Compensable 设置了5秒超时，而这个方法中 sleep 10秒，这会导致这个方法在 sleep的时候被 TimeoutProb 强制中断。

而日志中已经能明确看到 B 的补偿方法 cancel 方法已经被调用

2019-11-11 13:29:58.251 INFO 9180 --- [ault-executor-2] s.p.o.c.g.s.GrpcCompensateStreamObserver : Received compensate command, global tx id: 80465bee-caf7-4083-b401-2d149b0d2010, local tx id: af4cbf20-6b08-40d5-83ec-127fc2bcca5b, compensation method: public java.util.List com.example.microserviceB.service.BasicService.cancel()
2019-11-11 13:29:58.254 INFO 9180 --- [ault-executor-2] c.e.microserviceB.service.BasicService : B BasicService cancel()

但是我看到补偿方法 cancel 带一个返回参数，有可能是这个返回参数导致的吗 @WillemJiang @zhfeng

coolbeevip avatar Nov 11 '19 07:11 coolbeevip

我觉得Cancel方法返回参数应该不会有影响。

WillemJiang avatar Nov 11 '19 08:11 WillemJiang

我觉得Cancel方法返回参数应该影响。

感謝各位的指導，但補償不是必須滿足幕等的條件嗎 ? 那該怎麼設計補償呢 ? 謝謝

whitemeng avatar Nov 11 '19 08:11 whitemeng

測試把返回參數取消 image

serviceB 的 console log 如下，依然會重新連 alpha-server

2019-11-11 17:08:32.265 DEBUG 11860 --- [nio-9001-exec-1] o.a.s.p.o.transaction.TransactionAspect : Updated context OmegaContext{globalTxId=97425bdb-ecf1-4b92-b381-56c69a8186d4, localTxId=c5a38362-3c99-4982-a0d9-b81f817cb2c0, alphaFeatureAkkaEnabled=false} for compensable method public void com.example.microserviceB.service.BasicService.getNames() 2019-11-11 17:08:32.270 DEBUG 11860 --- [nio-9001-exec-1] o.a.s.p.o.transaction.DefaultRecovery : Intercepting compensable method public void com.example.microserviceB.service.BasicService.getNames() with context OmegaContext{globalTxId=97425bdb-ecf1-4b92-b381-56c69a8186d4, localTxId=c5a38362-3c99-4982-a0d9-b81f817cb2c0, alphaFeatureAkkaEnabled=false} 2019-11-11 17:08:37.271 WARN 11860 --- [ probe] o.a.s.p.o.t.wrapper.TimeoutProb : Thread interrupted on 5001ms timeout (over 5000ms) 2019-11-11 17:08:37.280 ERROR 11860 --- [nio-9001-exec-1] o.a.s.p.o.c.g.c.LoadBalanceSenderAdapter : Retry sending event TxEndedEvent{globalTxId='97425bdb-ecf1-4b92-b381-56c69a8186d4', localTxId='c5a38362-3c99-4982-a0d9-b81f817cb2c0', parentTxId='97425bdb-ecf1-4b92-b381-56c69a8186d4', compensationMethod='public void com.example.microserviceB.service.BasicService.cancel()', timeout=0, retryMethod='', retries=0, payloads=[]} due to failure

io.grpc.StatusRuntimeException: CANCELLED: Call was interrupted at io.grpc.Status.asRuntimeException(Status.java:517) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:129) ~[grpc-stub-1.14.0.jar:1.14.0] at org.apache.servicecomb.pack.contract.grpc.TxEventServiceGrpc$TxEventServiceBlockingStub.onTxEvent(TxEventServiceGrpc.java:273) ~[pack-contract-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcSagaClientMessageSender.send(GrpcSagaClientMessageSender.java:90) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender$1.apply(SagaLoadBalanceSender.java:45) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender$1.apply(SagaLoadBalanceSender.java:42) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.doGrpcSend(LoadBalanceSenderAdapter.java:54) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:42) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensableInterceptor.postIntercept(CompensableInterceptor.java:40) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.DefaultRecovery.applyTo(DefaultRecovery.java:70) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.wrapper.RecoveryPolicyTimeoutWrapper.applyTo(RecoveryPolicyTimeoutWrapper.java:111) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.AbstractRecoveryPolicy.apply(AbstractRecoveryPolicy.java:38) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.TransactionAspect.advise(TransactionAspect.java:66) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.example.microserviceB.service.BasicService$$EnhancerBySpringCGLIB$$fb05ffc5.getNames() ~[classes/:na] at com.example.microserviceB.controller.BasicController.names(BasicController.java:20) ~[classes/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na] Caused by: java.lang.InterruptedException: null at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1261) ~[na:na] at java.base/java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:317) ~[na:na] at java.base/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:430) ~[na:na] at io.grpc.stub.ClientCalls$ThreadlessExecutor.waitAndDrain(ClientCalls.java:629) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:123) ~[grpc-stub-1.14.0.jar:1.14.0] ... 87 common frames omitted

2019-11-11 17:08:37.283 DEBUG 11860 --- [nio-9001-exec-1] o.a.s.p.o.transaction.TransactionAspect : Restored context back to OmegaContext{globalTxId=97425bdb-ecf1-4b92-b381-56c69a8186d4, localTxId=97425bdb-ecf1-4b92-b381-56c69a8186d4, alphaFeatureAkkaEnabled=false} 2019-11-11 17:08:37.302 ERROR 11860 --- [nio-9001-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.apache.servicecomb.pack.omega.transaction.OmegaException: Failed to get reconnected sender] with root cause

java.lang.InterruptedException: null at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1261) ~[na:na] at java.base/java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:317) ~[na:na] at java.base/java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:453) ~[na:na] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:71) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:67) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.FastestSender.pick(FastestSender.java:39) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.pickMessageSender(LoadBalanceSenderAdapter.java:46) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:41) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensableInterceptor.onError(CompensableInterceptor.java:45) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.DefaultRecovery.applyTo(DefaultRecovery.java:74) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.wrapper.RecoveryPolicyTimeoutWrapper.applyTo(RecoveryPolicyTimeoutWrapper.java:111) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.AbstractRecoveryPolicy.apply(AbstractRecoveryPolicy.java:38) ~[omega-transaction-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.TransactionAspect.advise(TransactionAspect.java:66) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.example.microserviceB.service.BasicService$$EnhancerBySpringCGLIB$$fb05ffc5.getNames() ~[classes/:na] at com.example.microserviceB.controller.BasicController.names(BasicController.java:20) ~[classes/:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.1.10.RELEASE.jar:5.1.10.RELEASE] at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104) ~[spring-boot-actuator-2.1.9.RELEASE.jar:2.1.9.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.26.jar:9.0.26] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]

2019-11-11 17:08:37.696 INFO 11860 --- [ault-executor-1] s.p.o.c.g.s.GrpcCompensateStreamObserver : Received compensate command, global tx id: 97425bdb-ecf1-4b92-b381-56c69a8186d4, local tx id: c5a38362-3c99-4982-a0d9-b81f817cb2c0, compensation method: public void com.example.microserviceB.service.BasicService.cancel() 2019-11-11 17:08:37.700 INFO 11860 --- [ault-executor-1] c.e.microserviceB.service.BasicService : B BasicService cancel() 2019-11-11 17:08:37.700 INFO 11860 --- [ault-executor-1] o.a.s.p.omega.context.CallbackContext : Callback transaction with global tx id [97425bdb-ecf1-4b92-b381-56c69a8186d4], local tx id [c5a38362-3c99-4982-a0d9-b81f817cb2c0] 2019-11-11 17:08:45.702 ERROR 11860 --- [ault-executor-1] o.a.s.p.o.c.g.c.ReconnectStreamObserver : Failed to process grpc coordinate command.

io.grpc.StatusRuntimeException: CANCELLED: Failed to read message. at io.grpc.Status.asRuntimeException(Status.java:526) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:420) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:684) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:403) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:459) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:546) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:467) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:531) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) ~[grpc-core-1.14.0.jar:1.14.0] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na] Caused by: org.apache.servicecomb.pack.omega.transaction.OmegaException: Failed to get reconnected sender, all alpha server is down. at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:73) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.GrpcOnErrorHandler$GrpcRetryContext$1.get(GrpcOnErrorHandler.java:67) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.FastestSender.pick(FastestSender.java:39) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceSenderAdapter.pickMessageSender(LoadBalanceSenderAdapter.java:46) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender.send(SagaLoadBalanceSender.java:41) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.transaction.CompensationMessageHandler.onReceive(CompensationMessageHandler.java:36) ~[omega-transaction-0.5.0.jar:0.5.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:205) ~[spring-aop-5.1.10.RELEASE.jar:5.1.10.RELEASE] at com.sun.proxy.$Proxy114.onReceive(Unknown Source) ~[na:na] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:52) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:31) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:407) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33) ~[grpc-core-1.14.0.jar:1.14.0] at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:519) ~[grpc-core-1.14.0.jar:1.14.0] ... 5 common frames omitted

2019-11-11 17:08:45.703 INFO 11860 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 2019-11-11 17:08:45.718 ERROR 11860 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Failed to reconnect to alpha at 192.168.205.14:8080

io.grpc.StatusRuntimeException: UNKNOWN at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:222) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:203) ~[grpc-stub-1.14.0.jar:1.14.0] at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:132) ~[grpc-stub-1.14.0.jar:1.14.0] at org.apache.servicecomb.pack.contract.grpc.TxEventServiceGrpc$TxEventServiceBlockingStub.onDisconnected(TxEventServiceGrpc.java:280) ~[pack-contract-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcSagaClientMessageSender.onDisconnected(GrpcSagaClientMessageSender.java:75) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.PushBackReconnectRunnable.run(PushBackReconnectRunnable.java:52) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at org.apache.servicecomb.pack.omega.connector.grpc.core.PendingTaskRunner$1.run(PendingTaskRunner.java:44) ~[omega-connector-grpc-0.5.0.jar:0.5.0] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na] at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na] at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]

2019-11-11 17:08:48.720 INFO 11860 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 2019-11-11 17:08:48.725 INFO 11860 --- [pool-1-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at 192.168.205.14:8080 is successful

whitemeng avatar Nov 11 '19 09:11 whitemeng

@whitemeng 有包含所有代码及配置文件的工程可以共享吗？这样可以方便我们在本地重现这个错误。

zhfeng avatar Nov 11 '19 09:11 zhfeng

@whitemeng 有包含所有代码及配置文件的工程可以共享吗？这样可以方便我们在本地重现这个错误。

alpha-server 0.6.0 非狀態機模式 感謝 ! saga.zip

whitemeng avatar Nov 11 '19 10:11 whitemeng

我觉得Cancel方法返回参数应该影响。

感謝各位的指導，但補償不是必須滿足幕等的條件嗎 ? 那該怎麼設計補償呢 ? 謝謝 大概有两种方式实现：

  1. 补偿可以通过软删除的方式，通过设置cancel值来进行。具体可以参加我们的demo

  2. 这块可以通过全局事务ID和本地事务ID作为Key 在数据库中做相关的判断。 一般来说我们可以把事务执行的上下文存储到数据库中， 在恢复的过程中通过读取这些上下文进行相关的恢复。如果已经恢复成功，则不需要修改原始数据。

WillemJiang avatar Nov 11 '19 12:11 WillemJiang

Add a link of #346 which relates to this issue.

WillemJiang avatar Nov 11 '19 12:11 WillemJiang