Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Intermittent failure when running CustomersAndOrdersE2ETest after applying migration #59

Open
cer opened this issue Jun 7, 2022 · 1 comment
Open

Intermittent failure when running CustomersAndOrdersE2ETest after applying migration #59

cer opened this issue Jun 7, 2022 · 1 comment

Comments

@cer
Copy link
Contributor

cer commented Jun 7, 2022 •
edited
Loading

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 added a commit that referenced this issue Jun 7, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest
14ff6a7
cer added a commit that referenced this issue Jun 8, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest - add…
d452155 
…ed healthindication which checks dependencies
cer added a commit that referenced this issue Jun 8, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest - dis…
3e2b895 
…able DnsCaching
@cer
Copy link
Contributor Author

cer commented Jun 8, 2022

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

cer added a commit that referenced this issue Jun 8, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest - sto…
5b10312 
…p api-gateway-service
cer added a commit that referenced this issue Jun 8, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest - sto…
7ea478e 
…p api-gateway-service
cer added a commit that referenced this issue Jun 8, 2022
@cer
#59 Intermittent failure when running CustomersAndOrdersE2ETest - rev…
7d4a7f7 
…erted to stopping api-gateway-service
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@cer