(1)편에서는 설정을 중심으로 설명드렸고, 이번 (2)편에서는 실행 과정을 중심으로 말씀드리겠습니다. Tomcat 클러스터가 기동될 때 커넥터와 멤버십이 어떤 순서로 초기화되는지, 노드가 추가되거나 내려갈 때 어떤 이벤트가 발생하는지 디버깅 로그를 기준으로 정리했습니다.
1. Tomcat 기동 과정
먼저 org.apache.catalina.connector.Connector가 생성되고 서비스에 등록됩니다. HTTP/1.1 커넥터와 AJP/1.3 커넥터가 순서대로 추가되는 흐름입니다.
HTTP/1.1 connector 생성
StandardService.addConnector()
AJP/1.3 connector 생성
StandardService.addConnector() StandardEngine.setJvmRoute.routeId=node1 StandardService.setServer()
이후 Tribes 기반 클러스터 통신을 위한 Receiver와 멀티캐스트 멤버십 설정이 초기화됩니다.
org.apache.catalina.tribes.transport.ReceiverBase bind : McastServiceImpl.mcastAddress=/228.0.1.4 : McastServiceImpl.sendFrequency=500 : McastServiceImpl.expireTime=3000 : McastServiceImpl.port=45564 : McastServiceImpl.ttl=-1 : McastServiceImpl.soTimeout=-1
mcastAddress, sendFrequency 등 위 값들은 모두 server.xml의 SimpleTcpCluster에서 명시적으로 설정할 수 있으며, 설정하지 않을 경우 기본값이 적용됩니다.
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket INFO: Setting cluster mcast soTimeout to 500 : McastServiceImpl.setRecoveryCounter.recoveryCounter=10 : McastServiceImpl.setRecoverySleepTime.recoverySleepTime=5000 : McastServiceImpl.waitForMembers.level=4 Sleeping for 1000 milliseconds to establish cluster membership, start level:4 : McastServiceImpl.waitForMembers.level=8 Sleeping for 1000 milliseconds to establish cluster membership, start level:8
클러스터 매니저가 생성되면서 DeltaManager의 이름이 설정됩니다.
: SimpleTcpCluster.createManager.name= : DeltaManager.setName=Clone-from-null : DeltaManager.setName=localhost#
DeltaManager가 시작되면 클러스터 내 기존 세션을 가져오기 위한 동작이 이어집니다.
org.apache.catalina.ha.session.DeltaManager startInternal : DeltaManager.getName=localhost# : DeltaManager.getAllClusterSessions()
2. 기동 후 노드 추가와 제거
node1이 이미 기동된 상태에서 node2를 추가로 기동할 때 node1을 디버깅해 보면 다음과 같은 흐름을 확인할 수 있습니다.
Membership.memberAlive.entry=null Membership.addMember() McastServiceImpl.memberDataReceived.name=pool-1-thread-3 Membership.memberAlive.entry=null Membership.addMember() SimpleTcpCluster.memberAdded() DeltaManager.isSendAllSessions=true
반대로 node2를 내리면 다음 이벤트가 발생합니다.
SimpleTcpCluster.memberDisappeared()
즉, 노드 추가 시에는 멤버십 감지 후 memberAdded()가 호출되고, 노드 제거 시에는 memberDisappeared()가 호출되는 것을 확인할 수 있습니다.
3. 세션 생성
node1과 node2가 모두 기동되어 있는 상황에서 node1에 세션이 생성되면 다음과 같은 로그가 기록됩니다.
< node1 디버깅 >
DeltaManager.createSession.sessionId=null DeltaManager.createEmptySession() DeltaManager.getNewDeltaSession() StandardSession.activityCheck=null StandardSession.lastAccessAtStart=null StandardSession.ACTIVITY_CHECK=false setCreationTime.setAuthType=1396855430388 DeltaSession.setMaxInactiveInterval.interval=1800 DeltaRequest.setMaxInactiveInterval.interval=1800 DeltaSession.setId.id=5427FA09D116BDAA3B838B63F8D58A46.node1 DeltaRequest.setSessionId.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1 DeltaManager.sendCreateSession.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1 SessionManagerImpl.contextName=localhost# SessionManagerImpl.eventtype=1 SessionManagerImpl.sessionID=5427FA09D116BDAA3B838B63F8D58A46.node1 ClusterSession.requestCompleted.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1 ClusterSession.requestCompleted.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1 ClusterSession.requestCompleted.expires=false
< node2 디버깅 >
ClusterSessionListener.messageReceived.ctxname=localhost# DeltaManager.createEmptySession() DeltaManager.getNewDeltaSession() StandardSession.activityCheck=null StandardSession.lastAccessAtStart=null StandardSession.ACTIVITY_CHECK=false setCreationTime.setAuthType=1396855430388 DeltaRequest.setSessionId.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1 DeltaRequest.setSessionId.sessionId=5427FA09D116BDAA3B838B63F8D58A46.node1
node1에서 생성된 세션 ID가 .node1 형태의 jvmRoute 값을 포함하고 있고, node2에서도 동일한 세션 ID가 설정되는 흐름을 확인할 수 있습니다.
4. 세션 공유 주기
node1이 기동된 상황에서 node2를 기동하고, node2 측에 INFO: Server startup in ... ms가 기록되었다고 해서 곧바로 양 노드 간 세션 공유가 완료된 것은 아닙니다. 기존 node1에 다음과 같은 로그가 기록되어야 합니다.
ClusterSessionListener.msg.getEventType=4 ClusterSessionListener.msg.getEventTypeString=SESSION-GET-ALL ClusterSessionListener.messageReceived.ctxname=localhost# DeltaManager.isSendAllSessions=true SessionManagerImpl.contextName=localhost# SessionManagerImpl.eventtype=12 SessionManagerImpl.sessionID=SESSION-STATE SessionManagerImpl.contextName=localhost# SessionManagerImpl.eventtype=14 SessionManagerImpl.sessionID=SESSION-STATE-TRANSFERED Membership.addMember() SimpleTcpCluster.memberAdded()
위 이벤트에 의해 다음과 같은 로그가 남아야 서로 세션이 동기화된 것으로 볼 수 있습니다.
Apr 07, 2014 5:19:17 PM org.apache.catalina.ha.tcp.SimpleTcpCluster memberAdded
그런데 어느 때는 기동하자마자 Server startup 로그가 나오기도 전에 동기화가 되기도 하고, 어느 때는 기동 후 Server startup 로그가 나온 지 한참 뒤에 동기화되기도 합니다. 어떠한 주기가 있는 것 같은데 좀 더 확인이 필요합니다. Membership에서 receive()와 memberAlive()를 디버깅해 보면 설정된 것처럼 500ms마다 동작하고 있기는 합니다.
이 부분을 확인할 때는 단순히 서버 기동 완료 로그만 보지 말고, 기존 노드에서 SESSION-GET-ALL, SESSION-STATE, SESSION-STATE-TRANSFERED, memberAdded()가 실제로 찍혔는지를 함께 확인하는 것이 좋습니다. 테스트 시에는 node1에 세션을 하나 생성한 뒤 node2를 기동하고, 두 노드의 로그에서 동일한 세션 ID가 전달되는지 비교하면 동기화 여부를 더 명확히 볼 수 있습니다.
5. TcpFailureDetector
TcpFailureDetector는 기본 설정입니다.
node1과 node2가 모두 기동되어 있는 상황에서 node2를 내렸을 때의 디버그 로그입니다.
McastServiceImpl.memberDataReceived()
McastServiceImpl.memberDataReceived()
Membership.removeMember.name=tcp://{192, 168, 0, 102}:4000
Membership.removeMember.members.length=1
McastServiceImpl.memberDataReceived.t != null
TcpFailureDetector.memberDisappeared.Member.name=tcp://{192, 168, 0, 102}:4000
Membership.removeMember.name=tcp://{192, 168, 0, 102:4000
Membership.removeMember.members.length=1
SimpleTcpCluster.memberDisappeared.member.name=tcp://{192, 168, 0, 102:4000
SimpleTcpCluster.unregisterMember.member.name=tcp://{192, 168, 0, 102:4000
로그 흐름을 보면 멤버십에서 먼저 제거 대상 멤버를 감지하고, TcpFailureDetector가 해당 멤버의 장애를 확인한 뒤 SimpleTcpCluster.memberDisappeared() 및 멤버 unregister 과정으로 이어집니다. 따라서 장애 감지 테스트를 할 때는 멀티캐스트 수신 로그만 볼 것이 아니라 TcpFailureDetector.memberDisappeared와 SimpleTcpCluster.unregisterMember까지 이어지는지 확인해야 합니다.
