로그 모니터링 개발 기록 04. 검색엔진의 트러블슈팅

2021년 11월부터 현재(24년 1월)까지 약 2년동안 와탭 로그 모니터링을 개발하면서 배우고 느꼈던 것들을 정리하고 있습니다. 검색 엔진의 저장 구조, 조회 구조, 성능 최적화 그 다음으로 트러블슈팅을 다루고 있습니다. 트러블 슈팅 사례는 워낙 많았는데, 굵직 굵직한 선에서 정리해보겠습니다.

---

DFS에서의 시간 정렬 문제

이전 포스팅에서 DFS에 대한 설명을 간략히 언급한 적이 있습니다. 필요한 부분만 다시 요약하면, DFS Client가 검색 요청을 받아서 DFS Server로 실제 검색을 위임합니다. 그리고 각각의 DFS Server에서 검색된 내용을 DFS Client가 취합합니다. 그런데 이 과정에서 DFS Server는 각각 자신의 서버에 저장된 데이터 안에서만 시간을 기준으로 정렬된 상태입니다. DFS Sever → DFS Client로 수집되는 구간에서 다시 정렬이 보장되는 과정이 필요합니다.

DFS Client 에서의 정렬이 어떻게 수행되는지 간단히 설명해보겠습니다.

• DFS Server A에서 조회된 로그의 시간 0, 1, 2, 3
• DFS Server B에서 조회된 로그의 시간 0, 2, 2

각각의 DFS Server에서 수집된 로그의 시간이 위와 같다면 시간 0에 대해서 한 번 정렬 및 fetch를 수행하고, 그 다음에는 시간 1에 대해서 한 번 fetch하는 전략을 사용해야합니다. DFS Server A와 B에서 조회된 로그의 시간의 합이 [0,0,1,2,2,2,3] 이라고 해서, 이 시간들 전체에 대해서 정렬해서 fetch를 해버리면 안됩니다. 만약 [0,0,1,2,2,2,3]에 대해서 정렬해서 사용자에게 제공했는데, 아직 DFS Server B에서 시간 2의 데이터가 더 조회된다면 사용자에게는 시간 3 다음에 시간 2의 로그가 전달되는 상황이 발생합니다.

물론 ElasticSearch에서는 좀 더 우-아하게 이 문제를 푼 것 같습니다. 샤드를 나누어서 각각의 노드에서 색인을 하고, 노드끼리 서로 나눠서 진행한 색인을 공유받고, 하나의 노드에서만 검색을 수행합니다. 이론적으로는 DFS Client에서 시간을 기준으로 정렬하는 모델이 사라지기는 했는데.. 색인을 공유하는 과정이 더 만들기 어려운것 같습니다.

elastic search in action p.68

여기까지만 진행해서 정렬이 보장되면 참 아름답겠지만 세상은 그렇게 호락호락하지 않았습니다. 우선 와탭의 수집 서버와 고객 측 서버 시간이 1~2분 이상 차이나는 경우가 있을 수 있습니다. 색인 작업이 주기적으로 1~2분마다 수행되는 것을 고려하면 충분히 서버 시간의 차이만으로 색인과 검색에 오차가 발생할 수 있습니다.

게다가 AWS Resource 중에서 S3를 통해서 Log가 수집되는 대상들은, AWS CloudWatch LogGroup을 통해서 수집되는 로그들과 달리, N분마다 주기적으로 로그 데이터를 담고 있는 gzip 파일이 생성됩니다. 와탭의 수집 서버의 현재 시간 기준으로 N분전 시간을 가지고 있는 로그 데이터는 과거 시점의 데이터로 인식됩니다. 실시간으로 데이터가 수집되는 환경에서 현재 시간 데이터와 N분 전 데이터가 섞여서 들어와도 정렬이 보장된 상태로 저장하고 조회할 수 있어야합니다.

이와 같은 구조가 가능하려면, 색인 파일에 과거 시점에 수집된 데이터에 대한 색인을 (이미 존재하는 현재 시점의 색인을 유지한 상태로) append 하고 인식할 수 있어야 합니다. 하지만 현재의 로그 검색 엔진은 뒤 늦게 수집된 데이터의 색인을 append 할 수는 없는 구조로 되어 있습니다.

그래서 주기적으로 정렬하고 색인을 생성하고, 만약 과거 시점의 데이터가 수집되었다면 다시 색인 파일 전체를 읽어들이고 정렬을 하는 방법을 사용하고 있는데.. 이 방법만으로는 부족합니다. 사실 이렇게 접근하는 방법에서 어떤 상황이 고려되지 못한 것인지는 아직 알지 못했습니다. 버그 수정보다 버그의 원인을 찾는 과정이 더 어렵더라구요. byte 레벨까지 디버깅 해봤는데 결국 못찾았습니다. 그래도 다소 우회해서 이 문제를 해결할 수 있는 방법을 찾았고 적용했습니다.

https://docs.whatap.io/log/log-process

실제로 로그가 언제 생성되는지와 상관없이, 와탭 수집서버에 수집된 시간으로 타임스탬프를 지정했습니다. 로그가 발생한 시간과 와탭 수집 서버에 도달한 시간 사이에는 큰 차이가 없을 것이라는 가정 하에 적용된 방법입니다. 물론 앞서 말했던 N분마다 생성되는 배치 성격의 AWS LOG에 대해서는 다소 해석에 불편함 생긴다는 단점이 있습니다.

트랜잭션과 트랜잭선 로그

와탭 로그모니터링의 주요 어필 포인트 중 하나가 APM의 트랜잭션 정보와 해당 트랜잭션동안 발생한 로그 정보를 하나의 흐름으로 묶어서 조회하는 기능입니다. 가끔 신규 고객사분들 중에서 POC 과정에서 트랜잭션 로그 기능만 보시고 바로 계약하자고 하시는 분들이 있으실정도로 중요하고 핵심적인 기능입니다.

 

그런데 이렇게 중요한 기능인 트랜잭션 로그가 가끔씩 조회되지 않는 현상이 있었습니다. 트랜잭션 정보와 로그는 서로 다른 방식으로 각각 수집되는 데이터입니다. 따로 수집된 두 종류의 데이터를 각각 수집/저장한 뒤, transactionId라는 식별자를 통해서 각각 조회해서 하나의 연결된 화면으로 제공하는 방식을 사용합니다.

트랜잭션 로그가 가끔식 조회되지 않았던 현상의 원인은 트랜잭션 과정에서 발생한 로그의 시간은 트랜잭션의 시간과 큰 오차가 없이 수집될 것이라는 전제조건이었습니다. 이와 같은 가정하에 트랜잭선의 시간 +-3초정도의 시간을 기준으로 로그를 조회하고 있었는데, 이 때 사용되는 시간이 트랜잭션이 시작한 시간이었습니다. 만약 트랜잭션이 3초 이상 수행된다면 트랜잭션의 후반부에 생성/수집된 로그는 함께 조회되지 않는 것이었습니다.

트랜잭션과 관련된 로그를 조회하는 과정에서 transactionId를 색인으로 지정해서 검색하고 있습니다. 색인을 사용한 검색은 매우매우 빠르기 때문에 화끈하게 트랜잭션의 시작 시작 +- 1시간동안 수집된 로그를 검색하는 것으로 로직을 변경했습니다.

 

마치며

트러블 슈팅 사례는 내부 서비스 로직에 국한된 사례가 많아서 공유할 사항이 많지는 않네요. 그래도 시간 정렬에 대한 인사이트를 공유하는게 목적이었으니 충분히 누군가에게는 도움이 될 수 있을거라고 믿어봅니다.

 

 

혹시 로그 모니터링 개발 기록 시리즈 01 ~ 04를 모두 읽어주신 분이 계시다면..
진심으로 감사드립니다.