시스템 로그관리
로그는 코어로직을 블락시키면 안됨으로 쓰레드 안전한,비동기 Write를 지원해야한다.
로그는 5가지 레벨(Debug,Info,Error,Warn,Fatal)을 지원해야하며,개발 코드는 해당 레벨에 맞게 분리해야하며 운영중 해당 레벨은 변경될수 있습니다.
모든 개발로그(타팀개발)의 포맺은 통일되어,수집이되고 특정한툴 에서 쿼리를 통한 조회가 가능해야한다.
이 요건 충족하는 로그 라이브러리에는 자바진영에는 log4.j, 닷넷 진영에는 log4.net이 있으며 이러한 로그를 통합 수집/검색 가능한 툴에는 Splunk및 엘라스틱 서치(+로그스태쉬)가 있습니다.
운영중, 특정서버의 문제파악을위해 어플리케이션 다운없이 로그적는 정책을 변경할수 있어야합니다. ( 레벨을 Info에서 Debug로 변경)
– 이 기능으로 실시간 로그정책 변경가능 XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(”./conf/logset.xml”));
개발후,서비스 운영중 장애발생시 로그 분석에 대부분의 시간을 사용 하게되며, 장애는 언제 어떻게 발생할지 모르기 때문에, 로그 파악 만으로 서비스장애 및 사용자 트래픽수준을 파악할수 있을수 있게 아주상세하게 작성되어져야 합니다. 단 로그자체도, IO를 발생시키는 부분이기때문에 , 최대한 상세하게 작성후 중요한 로그/덜중요하거나 과도한 로그를 Info/Debug 레벨로 분리하거나, 과도한 로그중에서도 중요한 로그는 특정 텀(하트비트) 마다 작성하게 합니다.
그리고, 운영중 정상적인 Info로그의 시간대별 평균 기록량을 측정해두는게 중요합니다.
대부분 심각한 장애일시 Info로그 혹은 Error로그를 못적는 상황이 발생할수 있기때문에, Error나 Warn상황이 아니더래도 정상적인 Info 로그를 적고있지 않을시 장애검토 대상이기때문입니다.
과거(약10년전) 운영박스가 적을시에는 직접 로그시스템을 만들었으며 해당 로그를 Mysql로 수집하여 검색가능 웹툴로 만든적이 있습니다. 운영박스가 적을시에는, 개발자만이 알수있는 개발자 중심적 로그를 적을 시기였습니다. 과거 로그 수집 및 검색기를 손수 만드예:
하지만, 유져풀이 늘어남에 따라 운영팀이 생기고 서비스중 발생한 문제를 운영팀에서 쉽게 검색 가능해야 했으며 운영팀이 한국사람이 아니였기에, 로그는 운영팀에 제공해야 하는 또다른 서비스였습니다. Spunk대체로, 실제 로그검색을 활용한예: 실제 운영중 문제의뢰를 받아 검색한 케이스
검색키워드: Buyin (결제)
로그는 특정이벤트 조회, 특정 기간등의 조건으로 조회가 가능해야 하며 그래프화가 되어야 합니다. 그래프는 사용자 시도 트래픽 및 이상조건 판단때 유용한 정보입니다. 위와같이 특정노드 특정 시간에 그래프가 끊긴다면 서비스 이상으로 판단하고 문제 파악에 들어가야 합니다.
그리고, 시스템에서 로그를 적을수 없는케이스도 있습니다. 한가지 예를들면 사용자의 네트워크 혹은 , 특정 네트워크에 문제가 있는경우 사용자의 요청이 관리되는 서비스에 도달할수 없기 때문에 시스템 로그자체를 적을수 없으며, 그래프가 생기지 않는 조건입니다. 위 그래프 상황이 이와 유사한 상황일수 있으며,이러한 상황 판단을 위해, 다음 인터넷이 될 때 혹은 다음 요청시 , 유실된 문제의 정보를 수집하는 기능을(LastError) 만들기도 하였습니다. Restful의 케이스로 든다면, 이 문제 수집을 위해 특수한 API를 만들어 트래픽을 늘릴수는 없는일이라서,일반적 API의 Header값에 클라이언트의 발생한 마지막 Error번호를 같이 실어서 보내는 트릭을 활용하기도 하였습니다.
시스템 모니터링
시스템 이상 트리거를 스크립트로 등록가능해야하며, 필요하면 메일알림기능이 있어야함
모니터링 대상 운영박스는 그룹핑가능해야하며 실시간 및 과거 데이터 조회 가능해야함
체크대상은 시스템(CPU/Memory)뿐만 아니라 네트워크(단절,트래픽),서비스체크(IIS,PHP,DB..)가 가능해야함
과거에는, 시스템을 모니터링하기 위해 직접 어플리케이션을 만들어 사용했습니다. 기본적으로 서비스 제어가 가능했으며 CPU/Memory/패킷량등을 주기적으로 수집을 하여 문제발생시 매일 보고가능 기능이였습니다. 과거 손수제작한 모니터링툴 및 일일 보고예:
⇒붉은색 서비스 이상으로 체크대상 하지만 이역시, 운영박스가 늘어남에 따라, Enterprise급의 모니터링툴이 필요했으며, 도입된 것이 OpenNMS였습니다. 개발팀이 성장하고, 수익이 발생하는 시점 특정 도메인 서비스 개발에 집중을 하게되면 스타업일때 제작하였던 툴들을 오픈툴 혹은 상용툴로 교체하게됩니다.
OpenNMS변경후 특정노드 네트워크 트래픽 모니터링한 예: 실제 운영중 문제의뢰를 받아 검색시도
문제분석예: 일요일 18시 피크타임으로 추정되며, 그래프가 튀는현상(2곳) 발생 비정상 사용자 접속 종료로 보여지며, 해당노드에서만 발생하는문제인지, 전체적으로 발생한 네트워크 문제인지 추가조사필요 DB Error나 개발내부적으로 발생한 예외등은 명확한 문제 근거를 찾을수 있지만, 네트워크 단절은 가장 분석하기 어려운 부분이기 도 합니다.
대처방법 : 트래픽이 많은 패킷을 압축화하여, 트래픽을 줄여1차 해결 / 커넥션문제 체크를 위해 단절상황에 상세 Step별로 로그기록
어플리케이션 로그시스템을 통한 시스템모니터링 방식도 가능한 부분이지만, 분리하여 운영하는게 이상적이며
Spunk/ELastic Search 는 수집/검색/리포팅등 범용적인 부분에 특화가 되었다면, OpenPMS와 같은 모니터링 전용툴은 네트워크
및 각종 리소스수집/장애보고/장애감지트리거 등에 특화가 되어있으며 저장소부분을 ElasticSearch로 연동하여,
ELK에서도 조회가능할수 있게 연동할수가 있습니다.
이상적 로그 포맺과 활용법
에러 포맺...(공통화 필요)
|날짜시간 | 에러레벨 | 쓰레드번호 | APP이름 | 시도사용자 | API,기능이름 | 상세 로그 | 소요시간(적을수 있을시) |
[2017-07-28 12:58:30,963] [INFO] [1] [테스트APP] [1234564] [BuyinAPI] [Buyin Job Completed type:C domain:C
,00:00:02.345]
쓰레드번호: 쓰레드 번호를 적는이유? 동시 처리성체크를위해,
쓰레드 개수 최적화 체크및 성능조정을 위해서
시도사용자 : 사용자의 ID를 통해, 해당 사용자에게만 일어나는문제인지? 전체적으로 발생하는 문제인지 확인을 위해서,
사용자와 관련없는 시스템로그는 admin으로 기입
APP이름및 API이름 : 문제를 일으키는 코드를 빠르게 찾기위해서
( APP가 다중노드일시 APP_1 , APP_2 로 네이밍하여 특정노드만 발생하는 문제인지 빠르게 확인가능)
소요시간 : 주로 완료시 적을수 있으며, 시도-완료 시간의 성능 확인을 위해서,
완료시간-시도시간으로 계산가능하지만 기입시 성능 그래프화가능 (필수값은 아님)
한가지 기능(예>결제)에대해 진행 Step을 세분화해서 로그기록 ( 시도/완료or실패/경고로 스텝별 구분)
코드 표현예:
try{
log.info("결제시도됨......")
시도 코드
실패or성공 코드
log.ok("결제성공",시도후걸린시간) or log.error("결제실패")
}
exception(e){
log.warn(e.text + "성공했는지 실패했는지 모르겠음");
//시도 요청후, 대상 서버에서는 성공을 하였으나, Timeout이 발생하여 결과를 못받는 케이스
(돈은 결제되고,상품을 못받을수 있는케이스)
}
==> 로그를 위와같은 형태로 통일하지 않으면, 부모가 발생한 Exception을 자식도 책임안질시,
알수없는 상위 예외처리기에 의해 적힌 로그로는 해당문제 파악 불가능해짐
로그 패턴예 : 해당로그수는 그래프화가되어 수치화가 되어 비교할수 있어야합니다.
#정상적인 결제 완료
[2017-07-28 12:58:30,963] [INFO] [1] [결제APP_A] [1234564] [결제API_A] [결제가시도됨 {추가정보},NA]
==> 로그 분석방법 2017년 7월28일에 결제APP_A를 1234564 이용자가 결제 API_A를 이용해 결제가 시도됨
[2017-07-28 12:59:30,963] [INFO] [1] [결제APP_A] [1234564] [결제API_A] [결제가완료됨 {추가정보},00:00:01.234567]
#정상적인 결제 실패
[2017-07-28 12:58:30,963] [INFO] [1] [결제APP_A] [1234564] [결제API_A] [결제가시도됨 {추가정보},NA]
[2017-07-28 12:59:30,963] [ERROR] [1] [결제APP_A] [1234564] [결제API_A] [결제가취소됨 {결제실패 Step상세로그},00:00:01.234567]
==> 결제 실패 패턴이 많이 발생시, 명시된 ERROR라 할지라도 해당 세부 Step을 추적필요
#결제가 완료인지 실패인지 모르겠으나 실패로 추측
[2017-07-28 12:58:30,963] [INFO] [1] [결제APP_A] [1234564] [결제API_A] [결제가시도됨 {추가정보},NA]
[2017-07-28 12:59:30,963] [WARN] [1] [결제APP_A] [1234564] [결제API_A] [타이아웃 or 메모리풀 or 디스크풀등등이 발생함 ,00:00:01.234567]
==> WARN에서 메모리풀/디스크풀등이 발생시 FATAL로그 전환 ( 누적되다가 어플리케이션이 의도치 않게 죽게됨)
/ 실제 디스크풀일시는 로그적지못함
/ 메모리풀일시 일시적으로 작동가능 (가비지 컬렉트의 작동으로 메모리확보/풀 반복이일어나며 이로 인해 CPU 100에서 반복되다가 어플리케이션 뻗음)
==> FATAL이라고 판단할지라도 자기자신이 스스로 완료처리없이 어플리케이션을 CLOSE하는것은 위험합니다.
이경우 자신의 Health(하트비트 또는 헬쓰체크)를 남이 체크할수 있는 API를 만들어...., BIGIP(L4) 관리장비에서 특정노드
이상감지시...새로운 사용자가 해당노드에 접근못하도록 해당 노드 접근을 OFF하는 기능을 활용할수 있습니다.
#결제기능 오류
[2017-07-28 12:58:30,963] [INFO] [1] [결제APP_A] [1234564] [결제API_A] [결제가시도됨 {추가정보},NA]
==> 결제가 시도 되지만 완료및 에러가 없음 실제 장애시 많이 발생하는 케이스,"결제가시도됨" 로그수와
"결제가완료됨"+ "결제실패수" 로그수를 비교하여 특정시간에 문제가 발생하는건지?
특정 노드에서만 발생하는지 문제확인필요하며,
데드락/어플리케이션락/전역 Exception핸들링 처리로 발생할수 있는문제
정리
로그시스템과 모니터링 시스템은 별개일수 있으나,모니터링에 이상징후를, 로그 시스템에서 검색 또는 반대가 가능하여 서로 연관성을 찾는 것이 중요하다고 생각합니다. 모니터링 시스템의 특정구간 이상 징후가 발생할때, 실제 개발한 서버에서 로그를 발견할수 있다면 발생한 문제에 대해 개선할수 있는 지점을 찾을수 있는 중요한 단서가 될수 있습니다.
장애처리를위한 수집로그와 성능 모니터링이 갖추어져있다면, 이를 활용하여 성능튜닝/성능테스트/성능테스트 측정 등을 2차적으로 연계하여 진행할수가 있습니다.