[JBoss EAP 7] 세션 병렬 처리 관련 지원 ISPN000136/ISPN000299

===

https://coldplayer83.tistory.com/150

[ERROR] ISPN000136: Error executing command / ISPN000299: Unable to acquire lock after 15 seconds for key

===

 

ISPN000136/ISPN000299 에러 코드는 JBoss/WildFly/EAP에서

Infinispan 세션/캐시 처리 중 실행 오류가 날 때 로그에 찍히는 코드이다.

 

세션 클러스터 환경의 jboss 서버 로그에 다음과 같은 에러 발생하고,
여러 요청이 동일한 세션 ID를 참조하는 환경을 사용하는데, 

이로 인해 성능 문제가 발생하고 로그 파일에 오류 메시지가 나타남
 
Wildfly/JBoss는 기본적으로 동일 세션에 대한 병렬처리가 되지 않도록 설정되어 있다.

즉, 같은 웹 브라우저에서 1개의 롱 트랜잭션이 수행 될 경우,

해당 트랜잭션이 끝나기 전까지는 동일 웹 브라우저의 호출은 지연 및 에러가 발생

 

다른 WAS(Weblogic, Jeus 및 Tomcat) 에서는 발생하지 않는 현상으로 

Wildfly/Jboss 구성 간 반드시 고려해야 되는 사항
테스트는 다음과 같이 진행

1) 아래의 jsp 페이지를 긴 작업 실행을 한 번 누름

2) 긴 작업이 돌아가는 사이에 빠른 작업 실행을 한 번 클릭

3) 로그 확인 

 

15:52:44,158 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (non-blocking-thread--p6-t2) ISPN000136: Error executing command GetKeyValueCommand on Cache 'CON.war', writing keys
 []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key SessionCreationMetaDataKey(RE34AW70UkzbE1LGLUs8XnCL0wGeai_AQGaNS4QA) and requestor GlobalTra
nsaction{id=9, addr=node11, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=6, addr=node11, remote=false, xid=null, internalId=-1}
        at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:292)
        at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:222)
        at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.checkState(InfinispanLock.java:440)
        at org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lambda$toInvocationStage$3(InfinispanLock.java:416)
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591)
        at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:456)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49)
        at org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70)
        at java.lang.Thread.run(Thread.java:750)

15:52:44,172 ERROR [io.undertow.request] (default task-3) UT005023: Exception handling request to /CON/ispn000136_test.jsp: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acqu
ire lock after 15 seconds for key SessionCreationMetaDataKey(RE34AW70UkzbE1LGLUs8XnCL0wGeai_AQGaNS4QA) and requestor GlobalTransaction{id=9, addr=node11, remote=false, xid=null, internalId=-1}. Lock is held
 by GlobalTransaction{id=6, addr=node11, remote=false, xid=null, internalId=-1}
        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.CacheImpl.get(CacheImpl.java:540)
        at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:522)
        at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:439)
        at org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:696)
        at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:439)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.getValue(InfinispanSessionMetaDataFactory.java:103)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:93)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:54)
        at org.wildfly.clustering.web.cache.session.CompositeSessionFactory.findValue(CompositeSessionFactory.java:63)
        at org.wildfly.clustering.web.cache.session.CompositeSessionFactory.findValue(CompositeSessionFactory.java:40)
        at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:160)
        at org.wildfly.clustering.web.cache.session.ConcurrentSessionManager$2.apply(ConcurrentSessionManager.java:66)
        at org.wildfly.clustering.web.cache.session.ConcurrentSessionManager$2.apply(ConcurrentSessionManager.java:63)
        at org.wildfly.clustering.ee.cache.SimpleManager.apply(SimpleManager.java:52)
        at org.wildfly.clustering.web.cache.session.ConcurrentSessionManager.findSession(ConcurrentSessionManager.java:70)
        at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:229)
        at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:874)
        at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:964)

 

 

Solution

기동에 사용되는 config 파일 내부에서 수정이 필요

테스트 환경에서는 config 파일로 configuration/standalone-ha.xml을 사용하고 있어서 standalone-ha.xml을 수정

 

vi standalone-ha.xml

</distributed-cache name="dist"> , 이 부분을 아래와 같이 변경

READ_COMMITTED와 NONE으로 설정되어야 한다.

[app@test11 configuration]$ diff standalone-ha.xml standalone-ha.xml_260310_before_lock_15
402,403c402,403
<                     <locking isolation="READ_COMMITTED"/>
<                     <transaction mode="NONE"/>
---
>                     <locking isolation="REPEATABLE_READ"/>
>                     <transaction mode="BATCH"/>

 

이렇게 설정하면 더 이상 ISPN 관련 로그가 작성되지 않고 서비스가 정상적으로 동작하게 된다.

 

 

[테스트 용 jsp - ispn000136_test.jsp]

<%@ page language="java" contentType="text/html; charset=UTF-8" pageEncoding="UTF-8"
    import="java.util.Date" %>
<%
    request.setCharacterEncoding("UTF-8");

    String action = request.getParameter("action");
    if (action == null) {
        action = "view";
    }

    String resultMessage = "";
    long start = System.currentTimeMillis();

    if ("longTask".equals(action)) {
        // 세션 락 경쟁을 더 잘 유도하기 위해 동일 세션 객체를 오래 점유
        synchronized(session) {
            Integer cnt = (Integer) session.getAttribute("workCnt");
            if (cnt == null) cnt = 0;
            cnt = cnt + 1;
            session.setAttribute("workCnt", cnt);

            session.setAttribute("lastAction", "longTask start : " + new Date());

            // 오래 걸리는 업무 흉내
            Thread.sleep(70000);   // 70초

            session.setAttribute("lastAction", "longTask end : " + new Date());
            resultMessage = "긴 작업 완료. workCnt=" + cnt;
        }
    } else if ("quickTask".equals(action)) {
        synchronized(session) {
            Integer cnt = (Integer) session.getAttribute("workCnt");
            if (cnt == null) cnt = 0;
            cnt = cnt + 1;
            session.setAttribute("workCnt", cnt);

            session.setAttribute("lastAction", "quickTask : " + new Date());
            resultMessage = "빠른 작업 완료. workCnt=" + cnt;
        }
    } else if ("invalidate".equals(action)) {
        session.invalidate();
        resultMessage = "세션 무효화 완료";
    }

    long elapsed = System.currentTimeMillis() - start;
%>
<!DOCTYPE html>
<html>
<head>
    <meta charset="UTF-8">
    <title>ISPN000136 재현 테스트</title>
    <style>
        body { font-family: Arial, sans-serif; margin: 30px; }
        .box { border: 1px solid #ccc; padding: 15px; margin-bottom: 15px; }
        button { padding: 10px 14px; margin-right: 8px; }
        .warn { color: red; font-weight: bold; }
        .info { color: #333; }
    </style>
    <script>
        function openLongTask() {
            window.open("ispn000136_test.jsp?action=longTask", "_blank");
        }

        function openQuickTask() {
            window.open("ispn000136_test.jsp?action=quickTask", "_blank");
        }

        function runScenario() {
            // 1. 긴 작업 먼저 시작
            window.open("ispn000136_test.jsp?action=longTask", "_blank");

            // 2. 1초 뒤 같은 세션으로 빠른 작업 요청
            setTimeout(function() {
                window.open("ispn000136_test.jsp?action=quickTask", "_blank");
            }, 1000);
        }
    </script>
</head>
<body>
    <h2>ISPN000136 / 세션 락 경합 재현용 JSP</h2>

    <div class="box">
        <div class="info">현재 세션 ID: <%= session.getId() %></div>
        <div class="info">lastAction: <%= session.getAttribute("lastAction") %></div>
        <div class="info">workCnt: <%= session.getAttribute("workCnt") %></div>
        <div class="info">처리 결과: <%= resultMessage %></div>
        <div class="info">처리 시간(ms): <%= elapsed %></div>
    </div>

    <div class="box">
        <button onclick="openLongTask()">긴 작업 실행 (70초)</button>
        <button onclick="openQuickTask()">빠른 작업 실행</button>
        <button onclick="runScenario()">재현 시나리오 실행</button>
        <button onclick="location.href='ispn000136_test.jsp?action=invalidate'">세션 초기화</button>
    </div>

    <div class="box warn">
        테스트 방법:<br/>
        1. 같은 브라우저에서 "긴 작업 실행" 클릭<br/>
        2. 1~2초 후 "빠른 작업 실행" 클릭<br/>
        3. JBoss/WildFly/EAP 서버 로그에서 Infinispan / session / timeout / lock 관련 로그 확인
    </div>
</body>
</html>