SaiUpadhyayula/spring-boot-microservices

Order gets saved even after Resilience4j Time Limiter timeout

aamirxshaikh opened this issue · 0 comments

Description:

I'm encountering an issue where, despite the Resilience4j Time Limiter being applied to the placeOrder method in the OrderService class, the order is still getting saved after a timeout. I have checked my implementation, but I haven't been able to identify the root cause.

Expected Behavior:
The order should not be saved if a timeout occurs due to the Resilience4j Time Limiter.

Actual Behavior:
The order is still being saved even after the Time Limiter timeout.

Environment:

  • Spring Boot Version: 3.2.2
  • Resilience4j Version: 3.1.0
  • Java Version: 17

application.properties:

# Resilience4J Timeout Properties
resilience4j.timelimiter.metrics.enabled=true
resilience4j.timelimiter.instances.inventory.timeout-duration=3s
resilience4j.timelimiter.instances.inventory.cancel-running-future=true

OrderController:

@PostMapping
@CircuitBreaker(name = "inventory", fallbackMethod = "fallbackMethod")
@TimeLimiter(name = "inventory")
public CompletableFuture<String> placeOrder(@RequestBody OrderRequest orderRequest) {
  return CompletableFuture.supplyAsync(() ->
          orderService.placeOrder(orderRequest)
  );
}

InventoryService:

@SneakyThrows
@Transactional(readOnly = true)
public List<InventoryResponse> areItemsInStock(List<String> skuCodeList) {
    log.info("wait start");
    Thread.sleep(10000);
    log.info("wait end");

    return inventoryRepository.findBySkuCodeIn(skuCodeList).stream()
            .map(inventory ->
                    InventoryResponse.builder()
                            .skuCode(inventory.getSkuCode())
                            .isInStock(inventory.getQuantity() > 0)
                            .build())
            .toList();
}

Screenshots:

Screenshot from 2024-03-10 21-56-43

Screenshot from 2024-03-10 21-58-39

Logs:

2024-03-10T21:56:08.261+05:30 ERROR 10626 --- [order-service] [o-auto-1-exec-9] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] threw exception

java.util.concurrent.TimeoutException: TimeLimiter 'inventory' recorded a timeout exception.
	at io.github.resilience4j.timelimiter.TimeLimiter.createdTimeoutExceptionWithName(TimeLimiter.java:225) ~[resilience4j-timelimiter-2.1.0.jar:2.1.0]
	at io.github.resilience4j.timelimiter.internal.TimeLimiterImpl$Timeout.lambda$of$0(TimeLimiterImpl.java:185) ~[resilience4j-timelimiter-2.1.0.jar:2.1.0]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:842) ~[na:na]

2024-03-10T21:56:08.264+05:30 ERROR 10626 --- [order-service] [o-auto-1-exec-9] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.util.concurrent.TimeoutException: TimeLimiter 'inventory' recorded a timeout exception.] with root cause

java.util.concurrent.TimeoutException: TimeLimiter 'inventory' recorded a timeout exception.
	at io.github.resilience4j.timelimiter.TimeLimiter.createdTimeoutExceptionWithName(TimeLimiter.java:225) ~[resilience4j-timelimiter-2.1.0.jar:2.1.0]
	at io.github.resilience4j.timelimiter.internal.TimeLimiterImpl$Timeout.lambda$of$0(TimeLimiterImpl.java:185) ~[resilience4j-timelimiter-2.1.0.jar:2.1.0]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:842) ~[na:na]

2024-03-10T21:56:15.457+05:30 DEBUG 10626 --- [order-service] [onPool-worker-2] org.hibernate.SQL                        : 
    insert 
    into
        "order"
        (order_number) 
    values
        (?)
Hibernate: 
    insert 
    into
        "order"
        (order_number) 
    values
        (?)
2024-03-10T21:56:15.470+05:30 DEBUG 10626 --- [order-service] [onPool-worker-2] org.hibernate.SQL                        : 
    insert 
    into
        item
        (price, quantity, sku_code) 
    values
        (?, ?, ?)
Hibernate: 
    insert 
    into
        item
        (price, quantity, sku_code) 
    values
        (?, ?, ?)
2024-03-10T21:56:15.472+05:30 DEBUG 10626 --- [order-service] [onPool-worker-2] org.hibernate.SQL                        : 
    insert 
    into
        item
        (price, quantity, sku_code) 
    values
        (?, ?, ?)
Hibernate: 
    insert 
    into
        item
        (price, quantity, sku_code) 
    values
        (?, ?, ?)
2024-03-10T21:56:15.482+05:30 DEBUG 10626 --- [order-service] [onPool-worker-2] org.hibernate.SQL                        : 
    update
        item 
    set
        order_id=? 
    where
        id=?
Hibernate: 
    update
        item 
    set
        order_id=? 
    where
        id=?
2024-03-10T21:56:15.483+05:30 DEBUG 10626 --- [order-service] [onPool-worker-2] org.hibernate.SQL                        : 
    update
        item 
    set
        order_id=? 
    where
        id=?
Hibernate: 
    update
        item 
    set
        order_id=? 
    where
        id=?
2024-03-10T21:56:15.486+05:30  INFO 10626 --- [order-service] [onPool-worker-2] o.e.orderservice.service.OrderService    : order created : Order(id=1, orderNumber=ORD-58f14bcb-31f6-4204-b34a-76bc1f493f2d, items=[Item(id=1, skuCode=SKU123123, price=19.99, quantity=2), Item(id=2, skuCode=SKU456x, price=29.99, quantity=1)])

Possible Solutions (if any):
[If you have any suggestions on what might be causing the issue or how to fix it, provide them here]

Your help in resolving this would be greatly appreciated!