A Gotcha When Using ZooKeeper Ephemeral Nodes
미디엄을 만들어 놓고 너무 놀리고 있는 것 같아서 오래간만에 troubleshooting 시도하다가 발견한 골치아픈(?) 케이스를 공유
한글로 제목을 뽑아보려고 했는데 마땅한 제목이 떠오르지 않아서 참고한 문서의 제목을 훔쳐(?) 왔다.
ephemeral node 는 session 이 종료되면 삭제되는 것으로 보통 알고 있고 이를 기반으로 service discovery 등을 구축하는 데 사용하는데, node 의 삭제가 Zookeeper 서버 단에서 발생하기 때문에 Zookeeper 와의 연결이 비정상적으로 끊어진 경우 클라이언트에서 session 이 닫혔다고 로그가 남아도 Zookeeper 가 재시작되었을 때 ephemeral node 가 바로 삭제되지 않는 경우가 있다.
(추가) dump 를 보니 Zookeeper 서버 재실행 시 기존 Session Tracker 의 정보까지 다시 로드하는 듯 보인다. 즉, Zookeeper 서버를 내려도 session 들이 바로 close 되지 않고, 서버를 다시 실행해도 기존 session 들을 바로 expire 하지 않는 듯 보인다. 이런 이유로 session 은 유효하지 않은데 (클라이언트 기준) ephemeral node 가 남아 있을 수 있다. 내공이 얕아 또 다른 이유가 있는지는 모르겠다.
그래서 reconnect 이벤트 핸들러에서 해당 값을 재등록하도록 구현한 경우 이전 session 과 연관된 ephemeral node 가 현재 시점에 삭제되지 않았을 수도 있음을 감안해야 한다. 더 중요한 건, 해당 session 은 닫힌 상태이기 때문에 node 는 언젠가 (eventually) 삭제되게 되므로 해당 node 에 값을 기록하면 값을 날리게 된다는 것이다. (‘A’ session 이 만든 ephemeral node 에 ‘B’ session 이 값을 기록해도 ephemeral owner 는 바뀌지 않는다.) 안전한 구현은 node 를 먼저 삭제하고 기록하는 것이다.
ps. 너무 정보가 없는 것 같아서 transaction log 를 여는 방법과 snapshot 을 여는 방법이라도 남겨두려고 한다. 물론 출처는 Stack Overflow.
A. transaction log 읽기: zookeeper 설치 디렉토리에서 아래 명령 실행
java -cp zookeeper-3.4.6.jar:lib/log4j-1.2.16.jar:lib/slf4j-log4j12–1.6.1.jar:lib/slf4j-api-1.6.1.jar org.apache.zookeeper.server.LogFormatter version-2/log.xxx
B. snapshot log 읽기: zookeeper 설치 디렉토리에서 아래 명령 실행
java -cp zookeeper-3.4.6.jar:lib/log4j-1.2.16.jar:lib/slf4j-log4j12–1.6.1.jar:lib/slf4j-api-1.6.1.jar org.apache.zookeeper.server.SnapshotFormatter version-2/snapshot.xxx
ps2. 사실 이런 좋은 글을 찾긴 했었는데 실제로 빌드해서 돌려보니 NPE 가 발생해서 안 썼다. 일단 글의 설명으로는 상당한 기능을 갖고 있는 유틸리티이다. 작성자도 Zookeeper PMC 멤버인 듯 하다.
ps3. transaction log 에서 ephemeral node 를 추적할 때 삭제되는 시점을 알고 싶으면 ephemeral node 의 owner session 이 closeSession 으로 나타나는 로그를 찾으면 된다. deleteNode 로 로깅되지 않으니 주의.
7/5/16 5:56:10 AM KST session 0x155b7b136300007 cxid 0x0 zxid 0x280542 createSession 20000
7/5/16 5:56:10 AM KST session 0x155b7b136300007 cxid 0xd zxid 0x280544 create ‘/storm/nimbuses/<host>:6627,#1fffffff8b80000000ffffffe36660646060ffffffe036ffffffb434ffffffd23334ffffffb3ffffffd033ffffffd0ffffffb3ffffffe460606260ffffff907cffffffccffffffc1ffffffc01c5e7536ffffff8bffffff89ffffff81ffffff85ffffff81ffffff9bffffff8115ffffffa8ffffff86ffffffd510286bffffffc400ffffffe1ffffff80fffffffd5f31000,v{s{31,s{‘world,’anyone}}},T,214
7/5/16 6:00:10 AM KST session 0x155b7b60ee60003 cxid 0x3 zxid 0x280555 setData ‘/storm/nimbuses/<host>:6627,#1fffffff8b80000000ffffffe36660646060ffffffe036ffffffb434ffffffd23334ffffffb3ffffffd033ffffffd0ffffffb3ffffffe460606260ffffff907cffffffccffffffc1ffffffc01c5e7536ffffff8bffffff89ffffff81ffffff85ffffff81ffffff9bffffff8115ffffffa8ffffff86ffffffd510286bffffffc400ffffffe1ffffff80fffffffd5f31000,1
7/5/16 6:00:30 AM KST session 0x155b7b136300007 cxid 0x0 zxid 0x280557 closeSession null
ps4. session 및 ephemeral node 추적에는 zookeeper server 로 dump 를 날리는 것도 나쁘지 않다. session expire 예정 시간과 session 에 물려 있는 ephemeral node 들이 모두 나타난다.
echo ‘dump’ | nc localhost 2181 > zk-dump-`date +%Y-%m-%d-%H-%M-%S`.log
결과는 아래처럼 나타난다. (3.4.7 버전 기준)
SessionTracker dump:
Session Sets (7):
4 expire at Tue Jul 05 06:00:30 KST 2016:
0x155b7b136300006
0x155b7b136300007
0x155b7b136300005
0x155b7b136300008
0 expire at Tue Jul 05 06:00:32 KST 2016:
0 expire at Tue Jul 05 06:00:38 KST 2016:
0 expire at Tue Jul 05 06:00:40 KST 2016:
2 expire at Tue Jul 05 06:00:42 KST 2016:
0x155b7b60ee60001
0x155b7b60ee60000
2 expire at Tue Jul 05 06:00:44 KST 2016:
0x155b7b60ee60003
0x155b7b60ee60002
1 expire at Tue Jul 05 06:00:48 KST 2016:
0x155b7af6d610000
ephemeral nodes dump:
Sessions with Ephemerals (3):
0x155b7b136300005:
0x155b7b136300007:
/storm/nimbuses/<host>:6627
/storm/blobstore/test-topology2–4–1467185073-stormconf.ser/<host>:6627–1
/storm/blobstore/test-topology2–4–1467185073-stormcode.ser/<host>:6627–1
/storm/blobstore/test-topology2–4–1467185073-stormjar.jar/<host>:6627–1
0x155b7b60ee60002:
/storm/leader-lock/_c_88cee421-b78e-4795-a1df-61ea1abc9efc-latch-0000000221
