로그 설계 지침

개요

이 문서는 효율적이고 안정된 시스템 개발/운용을 하기 위한 로그 설계 지침이다.
정확하면서 낭비 없는 로그 출력을 목표로 한다.

로그 수준

로그의 긴급도나 용도에 따라서 다음처럼 로그 수준을 설정한다.
Log4j의 로그 수준을 따라하고 있어서 운용 상황에 따라서는 Critical 등 수준을 적절하게 추가하면 좋다.

PHP의 PSR-3에서는 더 세분화된 emergency, alert, critical, error, warning, notice, info, debug로 되어있다.

“출력지” “운용 시 대응”은 각 프로젝트의 정책에 준한다.

수준	개요	설명	출력지	운용 시의 대응
FATAL	치명적인 에러	프로그램의 비정상 종료를 수반하는 것.콘솔 등에 즉시 출력하는 것을 상정	콘솔 파일	즉각 대응이 필요
ERROR	에러	뜻하지 않은 기타 실행 시 에러.콘솔 등에 즉시 출력하는 것을 상정	콘솔 파일	영업 시간 내의 대응

수준	개요	설명	출력지	운용 시의 대응
WARN	경고	폐 요소가 된 API사용 API의 부적절한 사용 오류에 가까운 사상 등.실행시에 생긴 이상이라고 할 수 없지만 정상과도 다른 뭔가 뜻하지 않은 문제	콘솔 파일	다음 릴리스까지 대응
INFO	정보	실행 시 어떤 주목해야 할 사건(시작과 종료 등).메시지 내용은 간결하게 끊어야	콘솔 파일	대응 필요

수준	개요	설명	출력지	운용 시의 대응
DEBUG	디버깅	정보 시스템 동작 상황에 대한 자세한 정보	파일	출력하지 않는다
TRACE	트레이스	정보 디버깅 정보보다 더욱 상세한 정보	파일	출력하지 않는다

출력 위치

로그는 운용 담당자가 가능한 빨리 찾을 수 있는 장소에 출력한다.
파일에 출력하는 경우는 /var/log 등 알기 쉬운 디렉토리에 출력하고 적절한 퍼미션을 설정한다.
로그에는 시스템 내부의 중요한 정보가 출력되는 경우도 있으므로 Web의 공개 디렉토리, 퍼미션 777의 디렉토리 등 불특정 사용자가 접근 가능한 장소에는 출력해서는 안 된다.

표준 출력: 주로 배치 애플리케이션 등 콘솔에서 실행할 경우 도중 경과를 출력하는 경우 등에 사용한다.
표준 오류 출력: 주로 배치 애플리케이션 등 콘솔에서 실행할 때 오류가 발생한 경우 등에 사용한다. 표준 출력에 실행 결과를 출력하는 경우는 도중 경과 등에 사용되는 경우도 있다.
파일: 주로 콘솔 이외에서 실행하는 애플리케이션에 사용한다.

로그 메시지

메시지 파일로 묶고, 프로그램에 직접 하드 코딩하지 않는 것이 바람직하다.
기종(OS) 의존 문자는 사용하지 않는다. ASCII 문자만이 바람직하다. 멀티 바이트 문자를 사용하는 경우는 로그를 열람하는 환경에서 깨지지 않도록 주의한다.
최대한 간결하게 쉽고 출력할 것.
콘솔에서 확인하는 것을 고려하여 1행을 80문자 이내로 끝내는 것이 바람직하다.

포맷

보기 쉽고 운용을 고려한 포맷을 정한다. 다음은 일례.

헤더

개시 시간
처리 명칭
처리 대상
대상 건수

마감 시간, 소요 시간, 처리 결과
- OK/NG 등

BODY

처리 도중 경과
- ○건/○건 중
이벤트 내용
종류
- 로그 수준
- 대상 파일, 행수
- 조사 때 등 특히 이유 있는 경우를 제외하고 에러 시 이외는 스택 추적은 출력하지 않는다

출력 사례

Web애플리케이션에서의 출력 사례

INFO 레벨에서는 처리 내용, DEBUG 레벨에서는 HTTP Request/Response의 내용, SQL의 디버그 로그 등을 출력한다.
출력 내용이 많아지면 응답에 현저한 영향을 끼치기 때문에 Web 서버의 로그 등으로 대체 가능한 것은 활용한다(특히 스크립트 언어)

org.apache.log4j.PatternLayout 에 따른 포맷으로 아래와 같이 지정함으로 샘플 같이 출력된다

%-5p%d[%t]%m%n

처리 내용(정상 종료)

INFO  2015-10-30 15:44:01,836 [http-8080-4] START - /path/to/example is Called from getApplication.
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT email=user@example.com
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT password=******
INFO  2015-10-30 15:44:01,836 [http-8080-4] ID: 5003 - Success
INFO  2015-10-30 15:44:01,836 [http-8080-4] END - /path/to/example is Called from getApplication.

처리 내용(이상 종료)

INFO  2015-10-30 15:44:01,836 [http-8080-4] START - /path/to/example is Called from getApplication.
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT email=user@example.com
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT password=******
ERROR 2015-10-30 15:44:01,836 [http-8080-4] EXECUTE FAILURE! User registration
ERROR 2015-10-30 15:44:01,836 [http-8080-4] Cause by: WebServiceException - [ERR:1000] User exists
ERROR 2015-10-30 15:44:01,836 [http-8080-4] redirect to /path/to/error

디버그 로그

DEBUG 2015-10-30 15:44:01,822 [http-8080-4]

** before *****************************************: /path/to/example
  REQUEST_URI=/path/to/example
  CharacterEncoding=UTF-8, ContentLength=-1, ContentType=null, Locale=ja, Locales=ja, zh_TW, en, Scheme=http, isSecure=false
  SERVER_PROTOCOL=HTTP/1.1, REMOTE_ADDR=127.0.0.1, REMOTE_HOST=127.0.0.1, SERVER_NAME=localhost, SERVER_PORT=8080
  REQUEST_METHOD=POST, QUERY_STRING=null, PathInfo=null, RemoteUser=null
  Session SessionId=C5C2638BEDBD6553F000EF87E749CBAF
  Session :: CreationTime=1446186481217, LastAccessedTime=1446187436782, MaxInactiveInterval=1800
  [request]javax.servlet.forward.request_uri=/path/to/example
  [cookie]JSESSIONID=C5C2638BEDBD6553F000EF87E749CBAF
  [header]accept=text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  [header]accept-encoding=gzip, deflate
  [header]accept-language=ja,zh-TW;q=0.7,en;q=0.3
  [header]connection=keep-alive
  [header]cookie=JSESSIONID=C5C2638BEDBD6553F000EF87E749CBAF
  [header]host=localhost:8080
  [header]referer=http://localhost:8080/path/to/example
  [header]user-agent=Mozilla/5.0 (Windows NT 6.1; WOW64; rv:41.0) Gecko/20100101 Firefox/41.0
  [header]x-clickoncesupport=( .NET CLR 3.5.30729; .NET4.0E)
  [session]user=user@example.com

DEBUG 2015-10-30 15:44:01,835 [http-8080-4] BEGIN path.to#example()
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] BEGIN TRANSACTION tx=[FormatId=4360,

배치 애플리케이션에서의 출력 사례

콘솔에서 열람하는 것을 전제로 하고 있고, 1개에 80문자 이내에 들어가도록 하고, “year” 필드는 생략하고 있다.
중대한 애플리케이션의 경우는 밀리초 단위로 출력하는 경우도 있다.

org.apache.log4j.PatternLayout에 따른 포맷으로 다음과 같이 지정함으로써 샘플 같은 출력이된다

%-5p%d{MM/dd HH:mm:ss}%m%n

작업 개시

INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 BEGIN JobAB000000001
INFO  04/03 09:55:14 -----------------------------------------------------------

작업의 정상 종료

INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 FINISHED SUCCESSFUL JobAB000000001
INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 Total time: < 1 second
INFO  04/03 09:55:14 Finished at: Fri Apr 03 09:55:14 JST 2014
INFO  04/03 09:55:14 Final Memory: 6M/119M
INFO  04/03 09:55:14 -----------------------------------------------------------

작업의 이상 종료

INFO  04/03 10:25:22 -----------------------------------------------------------
ERROR 04/03 10:25:22 EXECUTE FAILURE! JobAB000000001
ERROR 04/03 10:25:22 Cause by: IOException - I/O Error!
INFO  04/03 10:25:22 -----------------------------------------------------------
DEBUG  04/03 10:25:22 Trace
java.io.IOException: I/O Error!
    at jp.example.job.JobAB000000001.execute(JobAB000000001.java:70)
    at jp.example.command.Main.main(Main.java:115)
DEBUG  04/03 10:25:22 -----------------------------------------------------------

경과

INFO  04/03 10:12:21 -----------------------------------------------------------
INFO  04/03 10:12:21 START - exampleMethod is Called from getApplication.
INFO  04/03 10:12:21 ID: 5002 - Skip (1/105)
INFO  04/03 10:12:21 ID: 5003 - Success (2/105)
... snip
INFO  04/03 10:12:21 END - exampleMethod is Called from getApplication.
INFO  04/03 10:12:21 -----------------------------------------------------------

출력 타이밍

다음과 같은 타이밍에 출력한다.

배치 어플리케이션의 경우

INFO 처리 개시시
INFO 경과
INFO 처리 종료 시
WARN 이벤트 발생 시
ERROR 예외 발생 시
INFO 기타 필요에 따라서

Web어플리케이션의 경우

HTTP Request/Response의 내용은 DEBUG레벨로 출력 시 RequestDumpFilter등을 사용하여 어플리케이션 내에서는 코딩하지 않는 것이 바람직하다.
PHP로 monolog를 사용하고 있는 경우는 EasyCorp/easy-log-handler를 사용하면 시정의 좋은 로그를 출력할 수 있다.

이하, INFO수준의 로그는 컨트롤러 클래스에서 최대한 간결하게 출력하는 것.

INFO 리퀘스트 개시시-처리 개요, 실행 클래스 이름, 메소드 이름
INFO 경과-실행 조건 처리 대상 객체의 핵심 가치 등(customer_id, order_id등)
INFO 처리 종료 시-실행 결과(OK/NG등), 리다이렉트처
WARN 이벤트 발생 시-화면에 표시된 에러 메시지 등
ERROR 예외 발생 시-예외 클래스 예외 메시지
INFO 기타 필요에 따라서

퍼포먼스에 대해서

로그 출력에 따른 성능 열화가 보일 경우는, 로그 설계를 재검토하기

로그 로테이션 간격

로그의 종류, 용량, 해석할 타이밍을 고려하고 로테이션 간격을 결정이다.
또 필요에 따라서 압축 처리를 한다.

로그의 보안

로그는 “이름”“주소”등 특정 개인을 식별하는 정보나 “전화 번호”나 “메일 주소”“SNS계정 정보”등 인터넷에서 개인과 연락을 하거나 개인의 소재를 알아낼 수도 같은 정보를 그대로 출력하지 않는다.
각 프로젝트의 개인 정보 보호 지침에 준거하고 다음과 같은 대책을 하는 것이 바람직하다.

1.출력하지 않는다
2.마스크 처리를 한다
3.식별성을 유지할 필요가 있는 경우는 한 방향 해시 함수를 사용하는 부호화하는

로그와 변경 이력

애플리케이션의 조작과 데이터의 변화를 로그에 기록하는 것은 중요하다.
하지만 로그는 어떤 액션이 발생한 것을 기록하는 데 담아 로그 확인을 위한 조작 이력과 데이터의 변경 이력 등은 별도 변경 이력 기능 등을 작성하는 것이 바람직하다.

TODO

로그 설계의 유용성을 추가한다
로테이션, 보존 기간의 지침을 추가하는
로그 관리에 대한 지침을 추가하는
로그의 감시에 대한 지침을 추가하는
콘솔 파일 이외의 출력지에 대해서 추가한다

이 글은 2019-05-04에 작성되었습니다.

Tagged:
log

jacking75