Lei Zhang created SCB-2004:
------------------------------
Summary: When the business service startup is not completed,
receiving a compensation request will cause gRPC and alpha to reconnect
Key: SCB-2004
URL: https://issues.apache.org/jira/browse/SCB-2004
Project: Apache ServiceComb
Issue Type: Bug
Components: Saga
Affects Versions: pack-0.6.0
Reporter: Lei Zhang
h1. If the Alpha's compensation call is received during the business service
startup process, compensation failure will occasionally occur
Because at startup, it will be connected to Alpha first, and then all
compensation methods will be scanned and put to the class CallbackContext, If
business service receives a compensation request before CallbackContext
initialization, you will get NullPointerExceptionBecause at startup, it will be
connected to Alpha first, and then all compensation methods will be scanned and
put to the class CallbackContext, If business service receives a compensation
request before CallbackContext initialization, you will get NullPointerException
```java public void apply(String globalTxId, String localTxId, String
parentTxId, String callbackMethod, Object... payloads) \{
CallbackContextInternal contextInternal = contexts.get(callbackMethod); <-----
this is empty String oldGlobalTxId = omegaContext.globalTxId(); String
oldLocalTxId = omegaContext.localTxId(); try {
omegaContext.setGlobalTxId(globalTxId);
omegaContext.setLocalTxId(localTxId);
contextInternal.callbackMethod.invoke(contextInternal.target, payloads);
if (omegaContext.getAlphaMetas().isAkkaEnabled()) { sender.send(
new TxCompensateAckSucceedEvent(omegaContext.globalTxId(),
omegaContext.localTxId(), parentTxId, callbackMethod)); }```
```20:06:03.549 [background-preinit] INFO
org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator
6.0.17.Final2020-06-16 20:06:03.801 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean
'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration'
of type
[org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$23824f27]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)
. ____ _ __ _ _ /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \
\( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \ \\/ ___)| |_)| | | | | || (_| | )
) ) ) ' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/ :: Spring Boot ::
(v2.1.6.RELEASE)
2020-06-16 20:06:04.543 INFO 33012 --- [ main]
o.a.s.pack.demo.car.Application : No active profile set, falling back
to default profiles: default2020-06-16 20:06:05.887 INFO 33012 --- [
main] o.s.cloud.context.scope.GenericScope : BeanFactory
id=0844c163-505d-340b-8e21-343d5198bae82020-06-16 20:06:06.024 INFO 33012 ---
[ main] trationDelegate$BeanPostProcessorChecker : Bean
'org.apache.servicecomb.pack.omega.transaction.spring.TransactionAspectConfig'
of type
[org.apache.servicecomb.pack.omega.transaction.spring.TransactionAspectConfig$$EnhancerBySpringCGLIB$$6fc18c0a]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)2020-06-16 20:06:06.186 INFO 33012 --- [
main] trationDelegate$BeanPostProcessorChecker : Bean
'org.apache.servicecomb.pack.omega.spring.OmegaSpringConfig' of type
[org.apache.servicecomb.pack.omega.spring.OmegaSpringConfig$$EnhancerBySpringCGLIB$$b6310c32]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)2020-06-16 20:06:06.217 INFO 33012 --- [
main] trationDelegate$BeanPostProcessorChecker : Bean
'omegaUniqueIdGenerator' of type
[org.apache.servicecomb.pack.omega.context.UniqueIdGenerator] is not eligible
for getting processed by all BeanPostProcessors (for example: not eligible for
auto-proxying)2020-06-16 20:06:06.244 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean 'alphaClusterAddress' of type
[org.apache.servicecomb.pack.omega.connector.grpc.AlphaClusterDiscovery] is not
eligible for getting processed by all BeanPostProcessors (for example: not
eligible for auto-proxying)2020-06-16 20:06:06.259 INFO 33012 --- [
main] o.a.s.p.omega.spring.OmegaSpringConfig : Discovery alpha cluster
address localhost:8080 from DEFAULT2020-06-16 20:06:06.269 INFO 33012 --- [
main] trationDelegate$BeanPostProcessorChecker : Bean
'alphaClusterConfig' of type
[org.apache.servicecomb.pack.omega.connector.grpc.AlphaClusterConfig] is not
eligible for getting processed by all BeanPostProcessors (for example: not
eligible for auto-proxying)2020-06-16 20:06:06.286 INFO 33012 --- [
main] trationDelegate$BeanPostProcessorChecker : Bean 'serviceConfig' of type
[org.apache.servicecomb.pack.omega.context.ServiceConfig] is not eligible for
getting processed by all BeanPostProcessors (for example: not eligible for
auto-proxying)2020-06-16 20:06:06.640 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean 'sagaLoadContext' of type
[org.apache.servicecomb.pack.omega.connector.grpc.core.LoadBalanceContext] is
not eligible for getting processed by all BeanPostProcessors (for example: not
eligible for auto-proxying)2020-06-16 20:06:06.711 INFO 33012 --- [
main] trationDelegate$BeanPostProcessorChecker : Bean 'sagaLoadBalanceSender'
of type
[org.apache.servicecomb.pack.omega.connector.grpc.saga.SagaLoadBalanceSender]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)2020-06-16 20:06:07.042 INFO 33012 --- [
main] o.a.s.p.o.c.g.c.LoadBalanceSenderAdapter : Alpha configuration is
\{AkkaEnabled=true}2020-06-16 20:06:07.045 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean 'omegaContext' of type
[org.apache.servicecomb.pack.omega.context.OmegaContext] is not eligible for
getting processed by all BeanPostProcessors (for example: not eligible for
auto-proxying)2020-06-16 20:06:07.069 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean 'compensationContext' of type
[org.apache.servicecomb.pack.omega.transaction.CallbackContext] is not eligible
for getting processed by all BeanPostProcessors (for example: not eligible for
auto-proxying)2020-06-16 20:06:07.085 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean 'coordinateContext' of type
[org.apache.servicecomb.pack.omega.transaction.CallbackContext] is not eligible
for getting processed by all BeanPostProcessors (for example: not eligible for
auto-proxying)2020-06-16 20:06:07.098 INFO 33012 --- [ main]
trationDelegate$BeanPostProcessorChecker : Bean
'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration'
of type
[org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$23824f27]
is not eligible for getting processed by all BeanPostProcessors (for example:
not eligible for auto-proxying)2020-06-16 20:06:07.286 INFO 33012 ---
[ault-executor-1] s.p.o.c.g.s.GrpcCompensateStreamObserver : Received
compensate command, global tx id: f8f70b2b-837a-4485-abc2-d99a399fd45f, local
tx id: 85d01500-c512-440d-8447-b793a9ca0bec, compensation method: void
org.apache.servicecomb.pack.demo.car.CarBookingService.cancel(org.apache.servicecomb.pack.demo.car.CarBooking)2020-06-16
20:06:37.400 ERROR 33012 --- [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:533)
~[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:442)
[grpc-stub-1.22.0.jar:1.22.0] at
io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:507)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:66)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:627)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:515)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInternal(ClientCallImpl.java:608)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:581)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
[grpc-core-1.22.0.jar:1.22.0] at
io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
[grpc-core-1.22.0.jar:1.22.0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[na:1.8.0_201] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[na:1.8.0_201] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_201]Caused
by: java.lang.NullPointerException: null at
org.apache.servicecomb.pack.omega.transaction.CallbackContext$CallbackContextInternal.access$200(CallbackContext.java:80)
~[classes/:na] at
org.apache.servicecomb.pack.omega.transaction.CallbackContext.apply(CallbackContext.java:53)
~[classes/:na] at
org.apache.servicecomb.pack.omega.transaction.CompensationMessageHandler.onReceive(CompensationMessageHandler.java:33)
~[classes/:na] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[na:1.8.0_201] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[na:1.8.0_201] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.8.0_201] at java.lang.reflect.Method.invoke(Method.java:498)
~[na:1.8.0_201] at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343)
~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE] at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:205)
~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE] at
com.sun.proxy.$Proxy99.onReceive(Unknown Source) ~[na:na] at
org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:52)
~[classes/:na] at
org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcCompensateStreamObserver.onNext(GrpcCompensateStreamObserver.java:31)
~[classes/:na] at
io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:429)
[grpc-stub-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
[grpc-api-1.22.0.jar:1.22.0] at
io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInternal(ClientCallImpl.java:596)
[grpc-core-1.22.0.jar:1.22.0] ... 6 common frames omitted
2020-06-16 20:06:37.402 INFO 33012 --- [pool-2-thread-1]
.a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at
localhost:80802020-06-16 20:06:37.409 ERROR 33012 --- [pool-2-thread-1]
.a.s.p.o.c.g.c.PushBackReconnectRunnable : Failed to reconnect to alpha at
localhost:8080
io.grpc.StatusRuntimeException: UNKNOWN at
io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:235)
~[grpc-stub-1.22.0.jar:1.22.0] at
io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:216)
~[grpc-stub-1.22.0.jar:1.22.0] at
io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:141)
~[grpc-stub-1.22.0.jar:1.22.0] at
org.apache.servicecomb.pack.contract.grpc.TxEventServiceGrpc$TxEventServiceBlockingStub.onDisconnected(TxEventServiceGrpc.java:326)
~[classes/:na] at
org.apache.servicecomb.pack.omega.connector.grpc.saga.GrpcSagaClientMessageSender.onDisconnected(GrpcSagaClientMessageSender.java:77)
~[classes/:na] at
org.apache.servicecomb.pack.omega.connector.grpc.core.PushBackReconnectRunnable.run(PushBackReconnectRunnable.java:52)
~[classes/:na] at
org.apache.servicecomb.pack.omega.connector.grpc.core.PendingTaskRunner$1.run(PendingTaskRunner.java:44)
[classes/:na] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[na:1.8.0_201] at
java.util.concurrent.FutureTask.runAndReset$$$capture(FutureTask.java:308)
[na:1.8.0_201] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java)
[na:1.8.0_201] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[na:1.8.0_201] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[na:1.8.0_201] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[na:1.8.0_201] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[na:1.8.0_201] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_201]
2020-06-16 20:06:37.453 INFO 33012 --- [ main]
o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s):
9001 (http)2020-06-16 20:06:37.475 INFO 33012 --- [ main]
o.apache.catalina.core.StandardService : Starting service [Tomcat]2020-06-16
20:06:37.475 INFO 33012 --- [ main]
org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache
Tomcat/9.0.21]2020-06-16 20:06:37.654 INFO 33012 --- [ main]
o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded
WebApplicationContext2020-06-16 20:06:37.654 INFO 33012 --- [ main]
o.s.web.context.ContextLoader : Root WebApplicationContext:
initialization completed in 33096 ms2020-06-16 20:06:38.049 WARN 33012 --- [
main] c.n.c.sources.URLConfigurationSource : No URLs will be polled
as dynamic configuration sources.2020-06-16 20:06:38.049 INFO 33012 --- [
main] c.n.c.sources.URLConfigurationSource : To enable URLs as dynamic
configuration sources, define System property
archaius.configurationSource.additionalUrls or make config.properties available
on classpath.2020-06-16 20:06:38.059 INFO 33012 --- [ main]
c.netflix.config.DynamicPropertyFactory : DynamicPropertyFactory is
initialized with configuration sources:
com.netflix.config.ConcurrentCompositeConfiguration@42066f0d2020-06-16
20:06:41.654 INFO 33012 --- [pool-2-thread-1]
.a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at
localhost:80802020-06-16 20:06:41.662 INFO 33012 --- [pool-2-thread-1]
.a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting to alpha at
localhost:8080 is successful2020-06-16 20:06:41.681 WARN 33012 --- [
main] c.n.c.sources.URLConfigurationSource : No URLs will be polled as
dynamic configuration sources.2020-06-16 20:06:41.681 INFO 33012 --- [
main] c.n.c.sources.URLConfigurationSource : To enable URLs as dynamic
configuration sources, define System property
archaius.configurationSource.additionalUrls or make config.properties available
on classpath.2020-06-16 20:06:43.305 INFO 33012 --- [ main]
o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService
'applicationTaskExecutor'2020-06-16 20:06:45.272 WARN 33012 --- [
main] o.s.c.n.core.CoreAutoConfiguration : This module is deprecated. It
will be removed in the next major release. Please use
spring-cloud-netflix-hystrix instead.2020-06-16 20:06:45.363 INFO 33012 --- [
main] o.s.b.a.e.web.EndpointLinksResolver : Exposing 2
endpoint(s) beneath base path '/actuator'2020-06-16 20:06:45.583 INFO 33012
--- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started
on port(s): 9001 (http) with context path ''2020-06-16 20:06:45.586 INFO 33012
--- [ main] o.a.s.pack.demo.car.Application : Started
Application in 42.974 seconds (JVM running for 43.721)2020-06-16 20:06:45.731
INFO 33012 --- [on(1)-127.0.0.1] o.a.c.c.C.[Tomcat].[localhost].[/] :
Initializing Spring DispatcherServlet 'dispatcherServlet'2020-06-16
20:06:45.731 INFO 33012 --- [on(1)-127.0.0.1]
o.s.web.servlet.DispatcherServlet : Initializing Servlet
'dispatcherServlet'2020-06-16 20:06:45.776 INFO 33012 --- [on(1)-127.0.0.1]
o.s.web.servlet.DispatcherServlet : Completed initialization in 45 ms```
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
