개요
예전에 재밌는 버그를 밟은적 있다. 코드는 아래와 같이 굴러갔다.
- 요청이 들어오면
- transaction 시작. 요청이 들어오면 트랜잭션이 시작되도록 프레임웍이 구현되어 있었다.
- 로그를 DB에 기록
- 로직을 적절히 수행
- transaction 완료. 요청 끝날때 트랜잭션이 끝남
로그를 왜 DB에 기록했는가? 몇가지 이유가 있었다.
하나는 검색이 쉬워서이다. 로그 테이블을 잘 만들고 로그를 잘 저장하면 검색이 쉽다. 아직도 터미널을 쓸 줄 모른느 컴맹이라서 grep 쓰는것보다 SQL이 쉽더라.
웹서버가 여러대였기에 DB를 쓰는게 편했다. 로그를 웹서버 로컬에 각각 기록하면 나중에 로그 파일을 뒤지기 위해 여러대의 웹서버를 열버봐야할텐데 그건 귀찮더라. DB서버같이 한곳에 모아두면 나중에 검색하는게 쉽다.
또한 일을 너무 크게 만들고 싶지 않았다. 로그 저장용 서버를 만드는(또는 준비하는) 것도 방법이다. 하지만 이를 위한 작업 자체가 귀찮았다. DB서버는 이미 있는거니까 할일이 별로 없어서 편했다.
적당히 구현해두니 적당히 돌아가더라. 그러던 어느날, 문제가 발생했다. 문제는 피할수 없는 것이다. 이를 위해 로그를 기록해뒀으니 문제를 고치는건 쉬울 것이다.
…라고 생각하고 로그 테이블을 열어봤는데 문제가 발생한 로그는 하나도 없었다. 이유는 간단하다. 문제 발생시의 흐름을 보자.
- 요청이 들어오면
- transaction 시작
- 로그를 DB에 기록
- 로직을 적절히 수행…하다가 펑!
- transaction rollback. 아까 기록한 로그를 지움
로그가 롤백 당하다니!!! 멍청하게 구현한 것의 대가를 결국 치뤘다.
대응: 트랜잭션과 로그 분리
트랜잭션 안에서 로그 남기는 것을 문제라고 생각한다. 로그 쓰는걸 트랜잭션 밖으로 뺀다. 그러면 트랜잭션이 롤백되어도 로그는 사라지지 않는다.
대응: 별개의 로그 시스템
DB에 로그를 남기는게 문제라고 생각한다. 로그를 DB와 관계 없는 곳에 기록했으면 트랜잭션이 롤백되어도 로그는 남을것이다.
원격 로그 서버
원격 로그 서버도 좋은 방법이다. 웹서버가 여러대 있어도 로그 서버에 로그가 집중되니 검색이 편하다. 게다가 별개의 시스템이니 로그가 롤백되는 일도 없다. 하지만 항상 좋다고는 못하겠다. 로그 기능을 구현할때 몇가지 요소를 생각해야한다. 그리고 그것이 만들어내는 결과물도 확인해야한다.
요즘 세상에 원격 로그 서버를 직접 구현하는 사람이 얼마나 있는지 모르겠다. 이미 구현된걸 갖다쓰는 사람이 많지 않을까? 로그 서버 구현체가 어떻게 동작하는지 확인해봐야한다. 저번에 작업한 프로젝트에서는 elasticsearch를 로그 서버로 사용했다. 그래서 elasticsearch에서 발생하는 사례를 주로 이야기할거다.
로그를 네트워크로 보낸다면 로컬에 로그를 쓰는것보다 시간이 훨씬 오래 걸릴 것이다. 로컬에 로그를 쓴다면 동기 방식으로 로그를 작성해도 심각하게 느리진 않을 것이다. 하지만 네트워크로 로그를 쓸때 동기 방식을 쓰면 네트워크 상태, 로그 서버의 상태등의 영향을 받아서 로그가 기록될때까지 너무 오래 걸릴 수 있다. 그래서 나는 비동기로 로그를 쓰도록 만들었다. 로그 보내는 워커 쓰레드가 있고 워커 쓰레드가 접근하는 작업 큐에 로그를 넣고 로직은 계속 진행하는 식으로 말이다.
원격 로그 서버를 쓴다는건 로그를 네트워크를 통해 보낸다는 소리이다. 네트워크를 통해 로그가 전달되니까 로그 작성 시간과 로그 도착 시간이 같을리 없다. 그래서 로그에 타임스탬프도 넣어서 보내주는게 올바른 방법이다.
이런 것들을 고려하면서 원격 로그 서버로 로그 보내는 기능을 만들고 사용해보니 재밌는 문제가 생기더라.
작업하다보니 짧은 시간동에 로그를 보내는 일이 있었다. 로그에는 timestamp가 붙어있으니까 elasticsearch에서 잘 보여줄거라고 믿었다. 근데 elasticsearch에서 로그를 검색해보니 순서가 뒤죽박죽이었다. 순서가 섞인 이유를 찾아보니 간단했다. 뒤섞인 로그의 timestamp가 전부 똑같았다. 나는 timestamp 잘 붙여서 보냈더니 로그 서버에 도착한 timestamp가 똑같다니 이게 무슨 소리야?
이것은 elasticsearch에서 제공하는 timestamp의 시간 정밀도가 밀리세컨트(ms)라서 발생한 문제였다. 로그를 짧은 간격동안 너무 많이 보내서 나노세컨트(ns)단위에서 timestamp가 다르면 elasticsearch에서 이를 제대로 처리하지 않는다. (추가 필드에다가 nanosecond 저장해두고 elasticsearch에서 제공하는 시간을 쓰지 말라는 소리도 있던데 이건 우회법이니까 일단 넘어가자)
다른 재밌는 문제도 있었다.
프로그램이 서버로 로그를 보냈다. 정확히는 로그를 작업큐에 넣었을 뿐이고 이것은 워커 쓰레드가 잘 처리해줄거다. 로그를 보내는것을 이런식으로 해서 비동기로 돌아가도록 만들었다. 그런데 로그를 보낸 직후에 프로그램이 죽어버리면 어떻게 될까? 워커 쓰레드가 작업 큐에서 로그를 꺼내기 전에 프로그램이 죽는다면? 네트워크로 로그를 보내는 도중에 프로그램이 죽는다면? 네트워크 서버의 상태가 하필이면 그때만 안좋아서 timeout 같은식의 에러가 발생했다면? 비동기로 로그를 쏘면 로그를 잃어버릴 가능성이 있다. 물론 로컬에 로그를 써도 비동기로 썼다면 잃어버릴 가능성이 있다. 기록되어야하는게 보장되는 로그는 동기로 쓰는게 좋은데 네트워크로 로그 보내는걸 동기로 대기 시간이 너무 오래 걸린다.
이것과 비슷한 문제도 있었다. API를 호출하면 로그를 네트워크로 제대로 쏘는지 확인하는 테스트를 작성했다. 테스트 코드의 흐름은 간단하다.
- API를 호출한다.
- API에서 아마도 네트워크로 로그를 보냈을거다.
- 로그 서버에서 로그를 꺼내본다.
- 꺼낸 로그가 아까 작성된 로그로 보이면 테스트 성공
실제로 돌리면 잘 안돌아간다. 로그를 비동기로 쐇기때문에 비결정론적으로 돌아간다. 비동기에서의 순서는 상상하면 안된다.
- API에서 로그를 쐈다.
- 네트워크로 로그를 쏘는 요청이 작업큐에 들어갔다.
- 로그 서버에서 로그를 꺼내본다.
- 새로 들어온 로그가 없네?
- 테스트 실패
- 워커 쓰레드가 작업큐의 내용을 꺼내서 로그를 보낸다.
이런식으로 돌아가는게 가능하다. 물론 이것만 있는건 아니다.
- API에서 로그를 쐈다.
- 네트워크로 로그를 쏘는 요청이 작업큐에 들어갔다.
- 로그 서버에서 로그를 꺼내본다.
- 새로 들어온 로그가 없네?
- 테스트 실패
- 테스트 실패했으니 테스트 프로그램이 종료됨.
- 로그 어디감?
테스트 코드에서 로그 쏘는건 mock object로 대신하거나 테스트 코드에 sleep같은걸 쓴다면 테스트는 통과하긴 한다. 하지만 원격 로그 서버가 문제 터지는 상황을 이야기하는거니까 일단 넘어간다.
로그 파일
로그파일은 로그 쓰기가 성공한다는게 높은 확률로 보장된다. (물론 실패할때도 있다. 디스크가 꽉차는 경우는 방법이 없다니) 반응도 빠르고 시간순으로 작성되도록 구현하는 것도 어렵지 않다. 다만 검색이 귀찮을뿐이다.
섞어쓰기
이번에 작업한 프로젝트에서는 원격 로그 서버와 로그 파일을 섞어썼다. 로그 서버는 elasticsearch를 사용했다. 로그는 로컬 파일에도 기록하지만 elasticsearch에도 기록했다. 둘의 장점을 얻을수 있다.
elasticsearch에 이상이 생겨서 로그가 제대로 기록되지 않거나 elasticsearch 서버의 용량 부족으로 옛날 데이터가 날아가면 로그 파일에서 복구할 수 있다. 로그 검색은 elasticsearch에서 하니까 쉽고 편하더라.
로그 파일을 원본 데이터로 쓰니까 로그 서버는 언제든지 바꿔도 된다. 새로운 로그 서버로 바꾸고 싶을때는 바꾸고 로그 파일의 데이터를 부어넣으면 잘 돌아갈거다. 로그 파일을 남겨두면 나중에 어떤식으로든지 가공해서 쓸 수 있다.
summary
- 롤백 당하지 않는다. 로그는 롤백되면 안되는 정보니까.
- 가공하기 쉽다. 원본 데이터로 쓸 수 있다.