[ERROR] ISPN000136 / WFLYCLWEBINF0004 / ISPN000299 15초 간격으로 반복되는 infinispan error

https://access.redhat.com/solutions/7085174

Getting infinispan error ISPN000136/WFLYCLWEBINF0004/ISPN000299 repeatedly at 15 second intervals - Red Hat Customer Portal

 

[에러]

아래와 같은 에러가 15초 간격으로 반복

2024-08-29 21:16:12,318 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p13-t1) ISPN000136: Error executing command RemoveCommand on Cache 'session-test.war', writing keys [SessionCreationMetaDataKey(rJp4WJ3Q8ILeWprpe3b_OmCKkKr-xihHdI5TXbd-)]: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key SessionCreationMetaDataKey(rJp4WJ3Q8ILeWprpe3b_OmCKkKr-xihHdI5TXbd-) and requestor GlobalTransaction{id=134, addr=node1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=5, addr=node2, remote=true, xid=null, internalId=-1} (pending)
        at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager.timeout(DefaultPendingLockManager.java:149)
        at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager.access$300(DefaultPendingLockManager.java:49)
        at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager$PendingLockPromiseImpl.onRelease(DefaultPendingLockManager.java:329)
        at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager$PendingLockPromiseImpl.call(DefaultPendingLockManager.java:294)
        at org.infinispan.util.concurrent.locks.impl.DefaultPendingLockManager$PendingLockPromiseImpl.call(DefaultPendingLockManager.java:247)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:750)

2024-08-29 21:16:12,327 WARN  [org.wildfly.clustering.web.infinispan] (LocalScheduler - 1) WFLYCLWEBINF0004: Failed to expire session rJp4WJ3Q8ILeWprpe3b_OmCKkKr-xihHdI5TXbd-: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key SessionCreationMetaDataKey(rJp4WJ3Q8ILeWprpe3b_OmCKkKr-xihHdI5TXbd-) and requestor GlobalTransaction{id=134, addr=node1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=5, addr=node2, remote=true, xid=null, internalId=-1} (pending)
        at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:255)
        at org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:298)
        at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:102)
        at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:84)
        at org.infinispan.cache.impl.CacheImpl.remove(CacheImpl.java:685)
        at org.infinispan.cache.impl.DecoratedCache.remove(DecoratedCache.java:542)
        at org.infinispan.cache.impl.AbstractDelegatingCache.remove(AbstractDelegatingCache.java:454)
        at org.infinispan.cache.impl.EncoderCache.remove(EncoderCache.java:720)
        at org.infinispan.cache.impl.AbstractDelegatingCache.remove(AbstractDelegatingCache.java:454)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.delete(InfinispanSessionMetaDataFactory.java:154)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.remove(InfinispanSessionMetaDataFactory.java:140)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.remove(InfinispanSessionMetaDataFactory.java:54)
        at org.wildfly.clustering.web.cache.session.CompositeSessionFactory.remove(CompositeSessionFactory.java:89)
        at org.wildfly.clustering.web.cache.session.CompositeSessionFactory.remove(CompositeSessionFactory.java:40)
        at org.wildfly.clustering.web.infinispan.session.ExpiredSessionRemover.remove(ExpiredSessionRemover.java:69)
        at org.wildfly.clustering.web.infinispan.session.ExpiredSessionRemover.remove(ExpiredSessionRemover.java:45)
        at org.wildfly.clustering.web.infinispan.session.SessionExpirationScheduler.test(SessionExpirationScheduler.java:101)
        at org.wildfly.clustering.web.infinispan.session.SessionExpirationScheduler.test(SessionExpirationScheduler.java:45)
        at org.wildfly.clustering.ee.cache.scheduler.LocalScheduler.run(LocalScheduler.java:140)
        ...
Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key SessionCreationMetaDataKey(rJp4WJ3Q8ILeWprpe3b_OmCKkKr-xihHdI5TXbd-) and requestor GlobalTransaction{id=134, addr=node1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=5, addr=node2, remote=true, xid=null, internalId=-1} (pending)
        ...

 

원인)

node2에서 끝나지 않은(in-flight) HTTP 요청이 세션 락을 잡은 채로 남아 있고, 그 상태에서 세션 만료(expire) 가 발생하자 primary owner(node1)에서 락을 못 잡아서 15초마다 실패 로그가 반복

 

1. node1, node2로 구성된 JBoss EAP 클러스터 기동

Infinispan 세션 캐시 정상, 세션은 특정 노드가 primary owner

 

2. node1으로 요청 → 세션 생성(JSESSIONID=abc.node1)
세션 ID: abc
라우팅 정보: node1
세션 primary owner = node1

3. JSESSIONID=abc.node1로 node2에 긴 요청 전송 💥Sticky Session 실패
원래 abc.node1 → node1로 가야 정상
➡️ node2가 node1 소유 세션을 건드림
➡️ node2에서 긴 요청(in-flight request) 시작
➡️ node2가 세션 락 획득

 

4. node1 종료
클러스터 리밸런싱 발생
세션 abc의 primary owner 변경: node1 => node2
이때 node2에서는 이미 진행 중인 요청이 존재(세션 락을 잡고 있음)

5. node1 재기동
다시 리밸런싱
primary owner : node2 => node1

 

💥문제 핵심
세션 primary owner = node1
하지만 락은 여전히 node2가 보유
node2의 요청은 아직 끝나지 않음

 

6. 세션 타임아웃 도래 (기본 30분)
jboss가 세션 expire 시도
primary owner(node1)가 락 요청
하지만 락 보유자 = node2 (in-flight request)
➡️ 15초 대기
➡️ Timeout
➡️ 예외 발생

 

7. Failed to expire session ... 에러가 15초마다 반복하여 발생
Infinispan 정책상 expire 실패 시 즉시 재시도
lock timeout = 15초

결과 : 15초마다 같은 에러 반복

 

---

 

해결)

세션 락을 잡고 있는 node2를 재기동하여 해결 = 락 강제 회수

 

[방법1] 긴 요청 종료
node2의 요청 끝남
락 해제
node1이 락 획득
세션 expire 성공
로그 종료

[방법2] node2 재기동
node2 클러스터 탈퇴
락 강제 해제
node1이 처리 완료