개요
예외처리에 대한 글에 왠 로그냐고 물을 수 있지만, 로그야 말로 예외 처리의 결과를 극대화 하는 수단 중 하나다.
현재 로그는 모든 상황에서, 최대한 많은 데이터를 수집하는 것을 목표로 하고 있는 시대다.
물론 모든 데이터를 수집하는 것은 비용과 관리 코스트를 포함하기에 쉽지 않은 선택이지만, 그 코스트를 감내하고 최대한 많은 사용자 지표를 얻어내려 하고 있다.
하지만, 이 글에서 말하고 싶은 것은, 그런 일반적 상황에서의 사용성 로그가 아닌, 오류 상황에서의 로그를 말하고자 한다.
현실
우리의 제품은 인기를 얻을 수록, 다수의 사양자에게 배포 된다.
다수의 사용자는 좀 더 다양한 사용 방식과, 다양한 기기, 다양한 환경으로 사용하게 된다.
이 중 일부 사용자가 겪는 문제가 있을 때, 이에 대한 추적이 불가능하다면 문제 해결은 제품이 지쳐 화가 나면서도, 사용을 포기 못한 충성 고객 일부가 겪고 불편한 과정 중 하나인 고객센터를 찾아 피드백하고, 여러 과정을 거쳐 개발 팀에 전달되고 나서야 해결 가능성이 생긴다. 부가적인 정보가 없다면 또 여러번의 핑퐁을 통해서야 겨우 수정되거나, 수정이 안되서 known issue가 되는 일도 비일 비재하다.
로그를 잘 남긴다면, 문제 상황에서 추가 정보를 즉각 확인 할 수 있을 뿐더러, 로그 취합을 통한 선제 대응도 가능하다.
로그를 남기는 이유는 우리의 제품에 오류가 생겼을 때, 의도치 않은 상황이 벌어졌을 때 주변 상황과 원인을 유추하기 쉽게 하기 위해 로그를 남겨야 한다.
그렇기에 현상에 원인을 줄 환경 변수를 취합해서 남겨야 한다.
코드 리뷰를 하다보면, 자주 나오는 얘기는 왜 이상황에서 로그를 남기지 않는가, 로그에 충분한 변수 정보가 부족할 때가 많다.
로그가 명확하다면, 수많은 케이스를 손쉽게 재현해 빠르게 수정이 가능해진다.
코드가 잘 격리되어있다면, 단위 테스트와 일부 Mocking 만으로도 재현이 가능해져, 같은 상황이 다시 반복되지 않도록 테스트 케이스를 추가 할 수도 있다.
결국엔 로그란, 이상 징후, 이상 현상, 의도치 않은 흐름 (보통 예외처리를 하고 return하는 경우가 많아, 흐름이 끊기는 상황도 발생한다), 예외 발생에 대한 정보 등을 개발팀에게 알려주는 힌트 제공자다. 심지어 이 힌트는 QA나 사용자의 현상 보고보다 정확한 정보를 잘 전달해주기 떄문에 반드시 잘 남겨야 한다.
아래는 개인적인 로그에 대한 규칙과 생각을 정리한 내용이다.
로그 규칙
- 별도의 로깅 함수 권장
- 예시
ToItemLog(),ToInventoryLog(),ToMatchLog(),ToShopLog(),ToTradeLog()등의 함수를 구현
ToString()같은 단일 로그 함수는 정보가 너무 많이 남아서, 클래스가 비대화해질수록 정보의 포화와 로그 용량이 지나치게 커질 수 있으므로, 용도별 분리가 좋다.- 또한 포매팅
- 예시
- 개행 지양
- 로그 파서에 따라 다른데, 개행을
- 로거는 다양하게 만들어두는 것이 유리함
- 로거 단위로 동적 on/off 기능을 매칭 시켜두기 때문에, 소수의 로거를 사용하면 레벨 조정이 어렵다.
- 로그 수위
- Trace 로그는 특수 디버깅용 로그
- 서비스 레벨에는 남지 않게 설정
- Trace 로그는 특수 디버깅용 로그
- 주요 변수
- 해당 로그가 찍히게 되는 상황을 유추할 수 있는 값을 기록
- 현재 클래스의 상황에 맞는 로그 함수 호출
- 아이템 획득시 오류의 경우
- 해당 캐릭터에 대한 로그 호출 ⇒
Character::ToItemLog() - 드랍 아이템 정보 ⇒
Item::ToDropLog() - 실패 원인 추정
- 이 현상으로 인해 벌어질 수 있는 사이드 이펙트
- 해당 캐릭터에 대한 로그 호출 ⇒
- 아이템 획득시 오류의 경우
- 현재 클래스의 상황에 맞는 로그 함수 호출
- 해당 로그가 찍히게 되는 상황을 유추할 수 있는 값을 기록
좋은 사례
- 필요한 정보가 모두 담겨있음. 포매팅은 개인마다 다르지만, 내용만으로도 크게 도움이 됨.
- Log
나쁜 사례
- 누가 실패난 것인지 알려주지 않는 로그
Log::Error("데이터를 찾지 못했습니다");- 나아진 예 ⇒
Log::Error("<UserId:{userId}> <MetaDataId:{metaDataId}> 연관된 메타 데이터를 찾지 못했습니다");
- 나아진 예 ⇒
- 로그 레벨이 잘못 지정된 로그
Log::Information("<UserId:{userId}> <MetaDataId:{metaDataId}> 연관된 메타 데이터를 찾지 못했습니다");- 나아진 예 ⇒
Log::Error("<UserId:{userId}> <MetaDataId:{metaDataId}> 연관된 메타 데이터를 찾지 못했습니다");
- 나아진 예 ⇒
- 어떠한 값이 어떤 위치인지, 로깅 코드를 봐야만 아는 로그
Log::Error("연관된 메타 데이터를 찾지 못했습니다 {userId} {metaDataId}");
- 해당 상황의 원인이 될 수 있는 값을 찍지 않는 로그
- 어떤 동작을 하고 있는지 기록하는 것이 좋다.
- 로그가 폭발할 수 있을 만큼 자주 불리는 함수에서 로깅
- 지금은 없지만… 로그로 인해 서버 처리 성능이 급감하므로 반드시 주의하자.
- 당연히 디스크 사용량도 급증한다.
- 특히 주기적으로 불려지는 함수에서 주의
- 지금은 없지만… 로그로 인해 서버 처리 성능이 급감하므로 반드시 주의하자.
로깅 할 때 떠올려야 할 것
- 함수
- 현재 실행 중인 함수가 어떤 함수인지
- 호출자 정보
- 이 함수를 누가 호출했는지에 대한 정보를 전달 받도록하자
- 함수에 넘기기 귀찮다면 Thread Local Storage를 이용해도 무방하다
- 은근히 이렇게 남겨둔 호출자 정보가 디버깅에 큰 도움이 되는 경우를 많이 봤다.
- 이 함수를 누가 호출했는지에 대한 정보를 전달 받도록하자
- 현재 상황
- 전달 받은 매개변수가 잘못됐거나
- 특정 값과 연관된 데이터를 찾지 못했거나
- DB 처리에 실패했거나
- 임계치를 넘어섰다거나
- 이 상황을 만든 변수
- 키 변수는 반드시 남겨라
- 해당 함수를 실행중인 주체, 여러 객체에 대한 처리 중이라면 누가 주체이며, 피대상자로써 처리중인지도 남겨야 한다.
- 명확하지 않지만, 현재 문맥에서 영향을 줬을 수 있는 변수
- 연관 데이터를 못찾았을 경우를 예를들면, 해당 연관 데이터용 키 값 하나만 떠오를 수도 있지만, 호출자 정보, 함수 자체에 넘어온 매개 변수 등도 같이 남기는 것이 유용할 수 있다.
- null 포인터 접근이 없는지 다시 한번 확인
- 로그를 남기는 과정에서 자주 하게 되는 실수는 로깅할 변수가 null 포인터인 상황에 있다.
- 이 상황이 발생함으로 인해 벌어질 수 있는 상황
- 보통 예외처리를 하는 로그를 남기고 return 하게 되곤하는데, 이렇게 된다면 어떠한 로직들이 처리가 안되고 반환되는지, 혹은 return값을 어떻게 핸들링해주어야 되는지 등을 로그에서 명시하는 것이 좋다. 예외처리 혹은 기능 구현한 사람의 의도를 (로그 양이 늘어날 지언정) 기록해준다면 이후 문제 해결에 큰 도움이 된다.