search

eventuate-tram / eventuate-tram-sagas-examples-customers-and-orders

Spring Boot/JPA microservices that use an orchestration-based saga to maintain data consistency
Other
520 stars 236 forks source link

Intermittent failure when running CustomersAndOrdersE2ETest after applying migration #59

Open cer opened 2 years ago

cer commented 2 years ago

CircleCI build

Test:

org.springframework.web.client.HttpClientErrorException$NotFound: 404 Not Found: "{"timestamp":1654591803477,"status":404,"error":"Not Found","path":"/orders"}"
    at org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:113)
    at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:168)
    at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:122)
    at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)
    at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:819)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:777)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711)
    at org.springframework.web.client.RestTemplate.postForObject(RestTemplate.java:437)
    at io.eventuate.examples.tram.sagas.ordersandcustomers.endtoendtests.CustomersAndOrdersE2ETest.shouldRejectBecauseOfUnknownCustomer(CustomersAndOrdersE2ETest.java:82)

API Gateway

2022-06-07 08:49:59.038 DEBUG [api-gateway,845eb61e78b63a87,845eb61e78b63a87] 1 --- [ctor-http-nio-3] o.s.w.s.adapter.HttpWebHandlerAdapter    : [59b7c92b-41] Completed 200 OK
2022-06-07 08:50:03.318 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-42] HTTP POST "/orders"
2022-06-07 08:50:03.488 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'myCircuitBreaker' succeeded:
2022-06-07 08:50:03.489 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:03.489019639Z[UTC]: CircuitBreaker 'myCircuitBreaker' recorded a successful call. Elapsed time: 168 ms
2022-06-07 08:50:03.492 DEBUG [api-gateway,,09b50d680ad82cef] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-42] Completed 404 NOT_FOUND
2022-06-07 08:50:03.578 DEBUG [api-gateway,,09b50d680ad82cef] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-43] HTTP POST "/customers"

2022-06-07 08:49:59.037 DEBUG [api-gateway,845eb61e78b63a87,845eb61e78b63a87] 1 --- [ctor-http-nio-3] .s.w.r.r.m.a.ResponseEntityResultHandler : [59b7c92b-41] 0..1 [org.springframework.boot.actuate.health.SystemHealth]
2022-06-07 08:49:59.037 DEBUG [api-gateway,845eb61e78b63a87,845eb61e78b63a87] 1 --- [ctor-http-nio-3] o.s.http.codec.json.Jackson2JsonEncoder  : [59b7c92b-41] Encoding [org.springframework.boot.actuate.health.SystemHealth@5736569d]
2022-06-07 08:49:59.038 DEBUG [api-gateway,845eb61e78b63a87,845eb61e78b63a87] 1 --- [ctor-http-nio-3] o.s.w.s.adapter.HttpWebHandlerAdapter    : [59b7c92b-41] Completed 200 OK
2022-06-07 08:50:03.318 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-42] HTTP POST "/orders"
2022-06-07 08:50:03.488 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'myCircuitBreaker' succeeded:
2022-06-07 08:50:03.489 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:03.489019639Z[UTC]: CircuitBreaker 'myCircuitBreaker' recorded a successful call. Elapsed time: 168 ms
2022-06-07 08:50:03.492 DEBUG [api-gateway,,09b50d680ad82cef] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-42] Completed 404 NOT_FOUND
2022-06-07 08:50:03.578 DEBUG [api-gateway,,09b50d680ad82cef] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-43] HTTP POST "/customers"
2022-06-07 08:50:03.816 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'myCircuitBreaker' succeeded:
2022-06-07 08:50:03.816 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:03.816483740Z[UTC]: CircuitBreaker 'myCircuitBreaker' recorded a successful call. Elapsed time: 235 ms
2022-06-07 08:50:03.820 DEBUG [api-gateway,,87172a44656aade4] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-43] Completed 404 NOT_FOUND
2022-06-07 08:50:03.830 DEBUG [api-gateway,,87172a44656aade4] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-44] HTTP POST "/customers"
2022-06-07 08:50:03.844 DEBUG [api-gateway,,] 1 --- [/api/v2/spans}}] o.s.w.r.f.client.ExchangeFunctions       : [1454eccb] HTTP POST http://zipkin:9411/api/v2/spans
2022-06-07 08:50:03.856 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-1] o.s.core.codec.ByteArrayEncoder          : [1454eccb] Writing 1779 bytes
2022-06-07 08:50:03.874 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-1] o.s.w.r.f.client.ExchangeFunctions       : [1454eccb] [934a879c-1, L:/172.18.0.7:57792 - R:zipkin/172.18.0.2:9411] Response 202 ACCEPTED
2022-06-07 08:50:03.896 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'myCircuitBreaker' succeeded:
2022-06-07 08:50:03.897 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:03.897005972Z[UTC]: CircuitBreaker 'myCircuitBreaker' recorded a successful call. Elapsed time: 64 ms
2022-06-07 08:50:03.899 DEBUG [api-gateway,,fbb17eb2b737f893] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-44] Completed 404 NOT_FOUND
2022-06-07 08:50:03.922 DEBUG [api-gateway,,fbb17eb2b737f893] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-45] HTTP POST "/customers"
2022-06-07 08:50:03.937 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'myCircuitBreaker' succeeded:
2022-06-07 08:50:03.937 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:03.937227933Z[UTC]: CircuitBreaker 'myCircuitBreaker' recorded a successful call. Elapsed time: 11 ms
2022-06-07 08:50:03.944 DEBUG [api-gateway,,f2e7eee6a39402ab] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-45] Completed 404 NOT_FOUND
2022-06-07 08:50:03.960 DEBUG [api-gateway,,f2e7eee6a39402ab] 1 --- [ctor-http-nio-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [bb3b5bd9-46] HTTP GET "/customers/1654591803949/orderhistory"
2022-06-07 08:50:03.964 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] o.s.w.r.f.s.s.RouterFunctionMapping      : [bb3b5bd9-46] Mapped to io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.customers.CustomerConfiguration$$Lambda$729/0x000000080111ee68@5aea5377
2022-06-07 08:50:03.968 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [64bb7906] HTTP GET http://customer-service:8080/customers/1654591803949
2022-06-07 08:50:03.971 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [6ab8b770] HTTP GET http://order-service:8080/orders/customer/1654591803949
2022-06-07 08:50:04.022 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [64bb7906] [fdc64cb6-1, L:/172.18.0.7:41576 - R:customer-service/172.18.0.9:8080] Response 404 NOT_FOUND
2022-06-07 08:50:04.022 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'MY_CIRCUIT_BREAKER' succeeded:
2022-06-07 08:50:04.022 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : Event SUCCESS published: 2022-06-07T08:50:04.022522655Z[UTC]: CircuitBreaker 'MY_CIRCUIT_BREAKER' recorded a successful call. Elapsed time: 55 ms
2022-06-07 08:50:04.036 DEBUG [api-gateway,,] 1 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [6ab8b770] [d52f6294-1, L:/172.18.0.7:44738 - R:order-service/172.18.0.8:8080] Response 404 NOT_FOUND
2022-06-07 08:50:04.051 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] o.s.w.r.f.client.ExchangeFunctions       : [6ab8b770] Cancel signal (to close connection)
2022-06-07 08:50:04.051 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] o.s.h.c.r.ReactorClientHttpResponse      : [d52f6294-1, L:/172.18.0.7:44738 - R:order-service/172.18.0.8:8080]Releasing body, not yet subscribed.
2022-06-07 08:50:04.082 DEBUG [api-gateway,a2b559bf7d349d6e,a2b559bf7d349d6e] 1 --- [ctor-http-nio-4] i.g.r.c.i.CircuitBreakerStateMachine     : CircuitBreaker 'MY_CIRCUIT_BREAKER' recorded an exception as failure:

io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.UnknownProxyException: Unknown: 404 NOT_FOUND
    at io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.OrderServiceProxy.lambda$findOrdersByCustomerId$0(OrderServiceProxy.java:43) ~[classes!/:na]
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly trace from producer [reactor.core.publisher.MonoFlatMap] :
    reactor.core.publisher.Mono.flatMap
    io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.OrderServiceProxy.findOrdersByCustomerId(OrderServiceProxy.java:38)
Error has been observed at the following site(s):
    *____________Mono.flatMap ⇢ at io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.OrderServiceProxy.findOrdersByCustomerId(OrderServiceProxy.java:38)
    |_           Mono.timeout ⇢ at io.github.resilience4j.reactor.timelimiter.TimeLimiterOperator.withTimeout(TimeLimiterOperator.java:63)
    |_          Mono.doOnNext ⇢ at io.github.resilience4j.reactor.timelimiter.TimeLimiterOperator.withTimeout(TimeLimiterOperator.java:64)
    |_       Mono.doOnSuccess ⇢ at io.github.resilience4j.reactor.timelimiter.TimeLimiterOperator.withTimeout(TimeLimiterOperator.java:65)
    |_         Mono.doOnError ⇢ at io.github.resilience4j.reactor.timelimiter.TimeLimiterOperator.withTimeout(TimeLimiterOperator.java:66)
    *__Mono.transformDeferred ⇢ at io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.OrderServiceProxy.findOrdersByCustomerId(OrderServiceProxy.java:46)
Original Stack Trace:
        at io.eventuate.examples.tram.sagas.ordersandcustomers.apigateway.proxies.OrderServiceProxy.lambda$findOrdersByCustomerId$0(OrderServiceProxy.java:43) ~[classes!/:na]
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:125) ~[reactor-core-3.4.17.jar!/:3.4.17]
        at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74) ~[reactor-core-3.4.17.jar!/:3.4.17]
        at org.springframework.cloud.sleuth.instrument.web.client.TraceExchangeFilterFunction$TraceWebClientSubscriber.onNext(TraceExchangeFilterFunction.java:197) ~[spring-cloud-sleuth-instrumentation-3.1.2.jar!/:3.1.2]

composeUp

Appears to recreate services but not API gateway

eventuate-tram-sagas-examples-customers-and-orders_mysql_1 is up-to-date
eventuate-tram-sagas-examples-customers-and-orders_api-gateway-service_1 is up-to-date
eventuate-tram-sagas-examples-customers-and-orders_zookeeper_1 is up-to-date
eventuate-tram-sagas-examples-customers-and-orders_zipkin_1 is up-to-date
eventuate-tram-sagas-examples-customers-and-orders_kafka_1 is up-to-date
eventuate-tram-sagas-examples-customers-and-orders_cdc-service_1 is up-to-date
Recreating eventuate-tram-sagas-examples-customers-and-orders_order-service_1 ... 
Recreating eventuate-tram-sagas-examples-customers-and-orders_customer-service_1 ... 
Recreating eventuate-tram-sagas-examples-customers-and-orders_customer-service_1 ... done
Recreating eventuate-tram-sagas-examples-customers-and-orders_order-service_1    ... done
cer commented 2 years ago

It appears to be caused by DNS caching in the JVM. The recreated customer service and order service containers switch IP addresses. Hence return 404s for requests intended for the other.

Before:

/eventuate-tram-sagas-examples-customers-and-orders_customer-service_1  908351bb2745fad8414fefd59f7384b280bfbfa4bc0451ac4433fe09fe5c73a3 172.18.0.8
/eventuate-tram-sagas-examples-customers-and-orders_order-service_1  eba19052b729dac4b387e4b952932cdbb89a9b9e48a8cb6ba1034bad7df230bf 172.18.0.7
/eventuate-tram-sagas-examples-customers-and-orders_api-gateway-service_1  4474318ffcea02710beefccbb26718b8fb2550bd7abe20f0c75fdab73ba71342 172.18.0.6

After 

/eventuate-tram-sagas-examples-customers-and-orders_order-service_1  3741b8cebad6b4c949c8b6cae71eac0baa0c43e16e4327a1c67a9bdd52c9c599 172.18.0.8
/eventuate-tram-sagas-examples-customers-and-orders_customer-service_1  67dc9b28bdff8315888c0cf7adca60a07a71ac8371cd76b22b6cb0abc25468d2 172.18.0.7
/eventuate-tram-sagas-examples-customers-and-orders_api-gateway-service_1  4474318ffcea02710beefccbb26718b8fb2550bd7abe20f0c75fdab73ba71342 172.18.0.6