Logging

2017-11-14

예전에 작성한 로깅 가이드를 올려봅니다

1. Logging 개요

1.1. Logging

프로그램의 실행에 관련된 기록(Record)를 남기는 행위. 기록(Record)를 Log(통나무)라고 부르는 이유는 기록된 내용을 봤을때 강물에 흘러가는 통나무 처럼 보이기 때문.

Logs in river

1.2. Logging Methods

기록을 남기는 방법은 다양함.

1.2.1. Printing

가장 기초적인 것은 프린팅.

System.out.println 을 이용해 정보를 콘솔(Console)에 출력하는 것.
try {
  System.out.println("Prepare connect to "+ ip +":"+port);
  connect(ip, port);
  System.out.println("Connected");
}
catch(Exception ex) {
  System.out.println("Fail to connect");
  ex.printStackTrace();
}

하지만 콘솔 모니터를 보고 있어야만 하고, 시간이 지나면 확인이 불가능하기 때문에 초기에 프로그래밍을 학습하는 시기에만 잠깐 쓰고 말아야 함

1.2.2. Logging Framework with file output

역사적으로 로그를 관리하기 위한 다양한 기술과 라이브러리가 개발되었다. 제가 추천하는 것은 SLF4J + Logback 이다.

나중에도 다시 볼수 있게 하기 위해 보통 파일에 로그를 저장한다

다음은 로그를 파일에 저장하는 설정이다

설정 파일: logback.groovy

appender("fileAppender", ch.qos.logback.core.FileAppender) {
   file = "/var/log/myapp.log"
}

(위 설정은 비동기성, 파일 롤링, 백업, 압축, 시간분할등 운영에서 필요한 설정을 싹 빼고 기술해본 설정입니다 ^^)

다음은 전체 설정입니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
import ch.qos.logback.classic.jul.LevelChangePropagator
import ch.qos.logback.classic.sift.MDCBasedDiscriminator

import com.fasterxml.jackson.core.JsonGenerator
import com.fasterxml.jackson.databind.MappingJsonFactory
import net.logstash.logback.composite.JsonProviders
import net.logstash.logback.composite.loggingevent.*
import net.logstash.logback.decorate.JsonFactoryDecorator

import java.nio.channels.spi.AbstractSelectionKey

import org.slf4j.bridge.SLF4JBridgeHandler


// Logback의 구동을 디버깅하기 위한 리스너 등록. 로그파일 갱신등의 상태 변화를 출력해줌
statusListener(OnConsoleStatusListener)

// JUL(Java Util Logging) to SLF4j 과정에서 발생하는 성능 저하를 막기 위한 조치  ( Ref: http://www.slf4j.org/legacy.html#jul-to-slf4j )
def lcp = new LevelChangePropagator()
lcp.context = context
lcp.resetJUL = true
context.addListener(lcp)

// JUL 대신 SLF4J를 사용하게 하였음
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();


// 동적으로 로그 설정을 하기 위해 JMX에 등록
jmxConfigurator()

// 로그 파일(logback.groovy)의 변화를 10초에 한번 검사하여 변경이 있을 경우 다시 읽기 한다
scan("10 seconds")


// 하나의 로그 파일로 여러 어플리케이션을 동시에 지원할수도 있음.
// 그럴경우 Application, Stage, Project Name, System Name등의 정보를 이용하여 별도의 파일에 기록하게 할수도 있음
// 하지만 여기에서는 단순하게 기술함

def SYMBOL = "my-app"

def STAGE = "P" // 운영 환경

// 로그 파일을 저장할 폴더. 프로젝트에 맞게 수정
def LOG_PATH_PREFIX = "/var/log/my-app"


// remoteAddr, requestId, programiId, userId 등의 메타 정보가 있어야 로그를 쉽게 분석 할수 있다
// 이런정보는 Servlet Filter나 Spring Interceptor등에서 Logback MDC를 이용해 주입할수 있다
// def CONSOLE_PATTERN = " %date{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%.-1level) %X{remoteAddr} %X{requestId:-00000000000000000000} %-20X{programId:-00000000000000000000} %X{uid} %red(%-17X{userId:-MB000000000000000}) %cyan(%-40.40logger{40}):%-4.4line - %message%n"

// 하지만 그런 설정을 하지 않았다면 단순하게 갈수도 있다
def CONSOLE_PATTERN = " %date{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%.-1level) %cyan(%-40.40logger{40}):%-4.4line - %message%n"


def consoleAppender = null
def CONSOLE = appender("CONSOLE", ConsoleAppender) {
  encoder(PatternLayoutEncoder) {
    pattern = CONSOLE_PATTERN
  }
  consoleAppender = component
}


// 로그를 저장하는 행위가 프로그램의 실행을 block 하지 않기 위해 비동기 Appender를 사용하게 한다
appender("CONSOLE_ASYNC", ch.qos.logback.classic.AsyncAppender) {
   component.addAppender(consoleAppender)
   includeCallerData = true // caller data는 appender에서 수집하게 되어 있다
}

def fileLogger = { PATH, SYMBOL , prudentMode->

  def fileAppender = null
  appender("${SYMBOL}_FILE", RollingFileAppender) {

    // TimeBasedRollingPolicy + prudent=true 에서는 file 속성을 설정하면 않된다. 설정해도 null로 변경함
    file = "${PATH}/${SYMBOL}.log"

    fileAppender = component //  component 는  appender 설정 내부에서 appender 자체를 가르키는 변수. ASYNC 에서 사용하기 위해 외부 변수에 저장해 둔다.
    encoding "UTF-8"

    // prudent가 true이면 여러 JVM이 동시에 로그를 저장할때 로컬 디스크든, 분산환경에서의 네트워크 디스크든 꼬이는 일 없이 저장되게 해주지만, 반대 급부로 막대한 성능 저하가 발생한다.
    // 또한 RollingFileAppender에 지정해준 file 속성은 무시되며 TimebasedRollingPolicy에 지정된 파일명을 사용하게 된다.
    prudent = prudentMode

    // 파일에 저장되는 로그 자체는 JSON 형태로 기록한다
    // JSON이 추후에 field를 추가하거나 중앙으로 수집하여 분석하기에 용이하다
    encoder(net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder) {

      jsonFactoryDecorator = (new JsonFactoryDecorator(){
        public MappingJsonFactory decorate(MappingJsonFactory factory){
          factory.disable(JsonGenerator.Feature.ESCAPE_NON_ASCII)
          return factory;
        }
      })

      def p =  new JsonProviders();

      p.addProvider(  new LoggingEventFormattedTimestampJsonProvider())

      p.addProvider(  new MdcJsonProvider())

      // 어플리케이션이 아니라 환경을 읽어 추가할수 있는 정보를 추가.
      // 실제 어플에서는 필요하지만 샘플에서는 비활성화 해둠
      // def  customFieldsProvider = new GlobalCustomFieldsJsonProvider()
      // customFieldsProvider.customFields =  '{"app":"'+APPLICATION+'","sysNo":"'+ SYSTEM_NO+'"}'
      // p.addProvider(customFieldsProvider)

      p.addProvider(  new LoggerNameJsonProvider())
      p.addProvider(  new LogLevelJsonProvider())
      p.addProvider(  new CallerDataJsonProvider())
      p.addProvider(  new StackTraceJsonProvider())
      p.addProvider(  new MessageJsonProvider())

      providers = p

    }
    rollingPolicy(TimeBasedRollingPolicy) {
      // aux: logback은 %d 로 나타낸 period를 롤링 스케줄로 삼는데 %d가 여럿 있을 때 어떤 것을 무시할지 지정할 때 사용
      // 로그 파일이 너무 커지면 다운 받거나 열어 보기가 힘들기 때문에 롤링 설정을 시간 단위로 하게 설정한다
      fileNamePattern = "${PATH}/backup/%d{yyyy-MM-dd,aux}/${SYMBOL}_%d{yyyy-MM-dd-HH}.log.gz"

      // 최대 몇개의 과거 로그파일을 유지할 것인가
      maxHistory = 24 * 31 * 6 // 롤링을 시간단위로 하기 때문. 6개월간 유지한다
    }
  }

  def asyncAppender = null

  appender("${SYMBOL}_FILE_ASYNC", ch.qos.logback.classic.AsyncAppender) {
    asyncAppender = component
      component.addAppender(fileAppender)
      includeCallerData = true // caller data는 appender에서 수집하게 되어 있다
  }
}

// Application Log

fileLogger(LOG_PATH_PREFIX, SYMBOL, false);




// 어플리케이션, 라이브러리마다 필요한 레벨이 다름

logger "jdbc.resultset" , ERROR
logger "jdbc.connection" , ERROR
logger "jdbc.audit" , ERROR
logger "jdbc.sqlonly" , ERROR
logger "jdbc.resultsettable" , ERROR
logger "jdbc.sqltiming" , ERROR
logger "log4jdbc.debug", ERROR

logger "net.sf.log4jdbc", INFO
logger "org.springframework.web.servlet.handler", WARN
logger "org.springframework", INFO
logger "org.springframework.security.web.util.matcher", WARN
logger "org.springframework.security.web.FilterChainProxy", WARN
logger "org.springframework.context.annotation", INFO

logger "org.mybatis.spring.SqlSessionUtils", ERROR
logger "org.apache.ibatis.io.ResolverUtil", INFO
logger "org.springframework", INFO
logger "org.hibernate",  INFO
logger "org.apache.commons.digester", INFO



//  개발중에만 필요한 로그들에 대한 설정.
if (STAGE != "P"){ //  운영환경에서는 설정되지 않아야 한다.
  logger "jdbc.resultsettable" ,  INFO
  logger "jdbc.sqlonly" ,     INFO
}


//  운영 환경이 아니면 콘솔 출력을  활성화 한다.  운영 환경에서는 중복 로그 기록에 따른 성능 하락을 방지 하기 위해 콘솔 출력을  disable  시킨다.
if (STAGE == "P"){
  root  INFO, ["${SYMBOL}_FILE_ASYNC"]

  //root  INFO, ["${SYMBOL}_FILE_ASYNC", "CONSOLE_ASYNC"]
}
else {
  root  DEBUG, ["${SYMBOL}_FILE_ASYNC",  "CONSOLE"]
}

설정은 이렇게 하고 그럼 로그는 코드상에서 기록하는 방법은 다음과 같습니다.

class MyApp {
  static final Logger log = Logger.getLogger(MyApp.class);

  public void doSomething() {
    log.debug("Enter Do something");
    // do something here
    log.debug("Exit do shometing");
  }
}

Logger를 사용하는 방법은 뒤쪽에서 상세히 기술하겠습니다.

1.2.3. Logging Framework with DB

실행 기록인 로그는 파일에만 저장하는게 아니고 당연히 DB에 저장할수도 있습니다. 물론 DB로 남기는게 합당할 경우에만 사용합니다. 이미 사용하고 계시는 이력 성격의 테이블이 실제적으로는 로그 역활을 수행하기도 합니다 . 하지만 아예 프로그래밍 로그를 DB에 저장하는 경우도 있기는 합니다. 보통 이런 성격의 로그는 감사 로그라고 부르며 DB에 기록하여 영구적으로 추적해야 하는 성격을 가집니다. (일반적인 로그는 보통 3개월에서 6개월정도 보관합니다)

여기서는 상세히 다루지는 않겠습니다.

1.3. Logger

자바에서 로그를 기록할때 로그 프레임워크 에 대한 Facade로써 Logger 객체를 사용합니다. 로그를 기록할때 보통 일정한 기준으로 그루핑할 필요가 있습니다. 보통 클래스 단위로 그루핑 하는게 일반적입니다.

class MyApp {
  static final Logger log = Logger.getLogger(MyApp.class);
}

요즘에는 Lombok을 이용하여 선언식으로 사용하기도 합니다

@Slf4j
class MyApp {
}

하지만 단일 클래스가 아니고 비지니스 단위로나 별도의 그루핑이 필요할때도 있습니다.

class Business1 {
  static final Logger log = Logger.getLogger("biz");
}

class Business2 {
  static final Logger log = Logger.getLogger("biz");
}

이렇게 기술된 Logger는 서로 같은 Logger를 공유하게 됩니다. 기록도 그루핑 되어 기록됩니다.

두가지를 혼용할수도 있습니다.

@Slf4j
class MyApp {
  static final Logger bizLog = Logger.getLogger("biz");
}--> log 와 bizLog를 사용할수 있습니다.

1.4. Log Details

로그를 기록할때 프린팅에서처럼 단순히 문자열만 기록할수도 있습니다만, 보통은 추가적인 정보를 같이 기록합니다. SLF4J의 기본 부가 정보는 다음과 같습니다.

  • logger: 어떤 Logger에서 기록한 로그인지를 나타냅니다.

  • timestamp: 기록된 시간

  • level: 로그의 레벨 TRACE, DEBUG, INFO, WARNING, ERROR

  • message: 프로그래머가 기록한 메시지

  • exception: 예외를 같이 기록한 경우 예외

  • threadName: 로그가 기록될때 사용된 쓰래드.

  • caller: 로그를 기록한 Caller 정보

  • class name:

  • file name:

  • method name:

  • line number:

등이 기록됩니다

많은 경우 이정도의 부가정보로 충분해 보입니다.

하지만 큰 규모의 웹 사이트를 운영하기 위해서는 추가적인 정보가 있으면 좋습니다.

  • remoteAddr: client ip. 접속한 사용자의 IP

  • requestId: request id 매 사용자 요청(Request)마다 부여 되는 고유 번호. 하나의 요청을 처리할때 로그는 많은수가 기록될수 있습니다. 이런 로그를 검색하고자 할때 유용합니다

  • app: application id 어떤 어플리케이션에서 기록된 것인가. 물론 일반적으로 어플리케이션 별로 로그파일을 만들기 때문에 불필요한 정보처럼 보입니다만,로그를 수집하여 처리 하기 위해서는 필요합니다

  • wasNo: 각 어플리케이션은 이중화된 WAS에서 동작하게 됩니다. 이때 현재 로그를 기록하는 게 어떤 WAS인스턴스인지 일수 있으면 유용합니다.

  • userId: 현재 로그를 사용하는 사용자에 대한 정보

  • sid: session id 비로그인 → 로그인 → 로그 아웃 등을 해도 사용자를 추적할수 있기 위해 사용자의 session을 추적할수 있는 정보가 있으면 유용합니다

  • programId: 어떤 프로그램을 통해 시작되어 기록되는 로그인지 알수 있으면 유용합니다.

  • referer: 어디에서 넘어온 요청인지 알수 있으면 유용합니다.

  • requestUri: 요청된 URI

  • host: 로그를 기록한 호스트 머신의 호스트명

1.5. Logging Level

로그를 기록할때 고려해야 하는 것중에 중요한 것은 성능, 간결성, 설명가능성의 균형을 잡는 것입니다. 모든 변경, 수행에 대해 상세히 로그를 기록한다면 설명 가능성은 높아지겠지만, 성능(CPU, Disk용량)은 낮아질것입니다.

또 너무 많은 로그는 간결하지 못해서 중요한 내용을 쉽게 파악하지 못하게 됩니다.

하지만 너무 적은 로그를 기록하면 빠르고 간결하겠지만, 문제가 발생했을때 설명을 얻기 어려워 집니다.

이런 문제를 해결하기 위해 우선적으로 고려 해야 하는 것이 Logging Level입니다. (다음에 기술할 Logging Domain이 더 큰 주제입니다만, 기술적으로 바로 적용할수 있는것이 Logging Level입니다)

1.5.1. Level

TRACE

이 레벨을 자주 사용하지는 않으며, 개발 중에도 보통은 사용하지 않는 매우 상세하고 잠재적으로 대량의 로그를 위해 사용됩니다. 예를 들어, 전체 객체 계층 구조를 덤프하거나 대형 루프를 반복 할 때마다 상태를 기록하는 등의 작업을 수행 할 수 있습니다.

DEBUG

INFO까지는 못되지만, 시스템을 통한 흐름을 추적하고 특히 개발 및 품질 보증 단계에서 문제를 격리하는 데 도움이되는 모든 메시지. 대부분의 중요하지 않은 메소드의 시작 / 종료에 대해 "디버그"레벨 로그를 사용하고 메소드 내에서 흥미로운 이벤트와 결정 포인트를 표시합니다.

INFO

과학적으로 문제를 분석해야 하는 경우에 대비하여 대량으로 보고싶은것. 시스템 생명주기 이벤트(시스템 시작, 종료), 세션 생명주기 이벤트(로그인,로그아웃, ETC) 등이 대표적입니다. 중요한 경계 이벤트(DB호출, 원격 API 호출)도 대상이 됩니다. 비지니스 예외도 해당 됩니다.(잘못된 암호때문에 로그인에 실패했다던가, 카드번호가 틀려서 결제에 실패 했다던가) 운영환경에서 대량으로 볼 필요가 있다고 생각되는 다른 이벤트도 해당됩니다.

WARNING

예상치 못한 기술이나 비즈니스 이벤트가 발생하면 고객에게 영향을 미칠 수 있지만 즉각적인 사람 개입이 필요하지 않을 수 있습니다. 기본적으로 추적해야 할 문제가 즉시 대응이 필요하지는 않은 것이 대상입니다.

ERROR

시스템에 장에가 발생하거나 고객이 영향을받을 가능성이 있거나 (또는 곧 그렇게 될거 같거나), 프로그램에 수정에 사람이 개입이 필요한 내용에 대한 레벨입니다. "2AM 규칙"이 여기에 적용됩니다. 전화를 걸면이 상황이 발생하면 오전 2시에라도 일어나야 하는 내용이라면 "ERROR"로 기록해야 합니다 많은 프로그래머가 운영에서도 로그를 보고 싶다는 이유로 TRACE나 DEBUG레벨에 적합한 내용을 INFO로 기록하는 경우가 많습니다. 이것은 운영중에 불필요한 로그를 계속 보게 되는 이슈가 발생합니다.

Logback 설정은 실행중에도 설정파일의 변경을 감지하여 재설정이 가능하여 런타임에 특정 Logger의 기록 레벨을 바꿀수 있으니 해당 기능을 이용해 추가적인 로그를 남기게 하는게 좋습니다.

1.6. Log Domains

로그를 남기는 이유는 몇가지로 분류될수 있습니다.

1.6.1. 개발 로그(Development Log)

개발자가 디버깅 및 흐름 추적을 위해 기록하는 내용입니다.보통 debug, trace레벨로 기록합니다.

1.6.2. 운영 로그(Maintenance Log)

운영에 관련된 로그입니다. 디스크가 꽉 찼거나, 인터페이싱 과정에서 타입아웃이 발생했거나 하는등 운영을 모니터링하기 위한 용도의 로그입니다. 보통 WARNING이나 ERROR로 기록됩니다.

1.6.3. 비지니스 로그(Business log)

비지니스적으로 의미가 있고 추후 추적하기 위한 로그입니다. 장바구니 상품추가, 로그인, 결제등이 대표적입니다. 보통 INFO로 기록합니다.

1.6.4. 감사 로그(Audit log)

감사 로그는 보안 관련 시간순 기록, 기록 집합 및 / 또는 대상 및 기록 데이터 소스입니다. 특정 작업, 절차 또는 기록에 언제든지 영향을 미친 활동 순서에 대한 증빙 자료를 제공하기 위해 기록됩니다. 보통 INFO이지만 운영자가 수정가능하지 않는 곳에 저장합니다.

1.7. 로그로 남기면 좋은 것들

  • 중요한 기동관련 설정

  • 에러

  • 경고

  • DB에 저장해야 하는 변경된 데이터

  • 주요 시스템간 요청과 응답

  • 중요한 상태 변화

  • 사용자 Interaction

  • 실패할 가능성이 있는 호출

  • 특정 상태를 기다리는데 시간이 걸릴때

  • 오래 걸리는 작업에 대해 주기적으로 진행상태 기록

  • 중요한 로직 분기점과 그 분기로 이끈 상태

  • 고수준 함수를 처리하는 스텝이나 이벤트에 대한 요약 ( 저수준 복잡한 프로세스의 매 스텝마다 로그를 남기는것은 피할것)

1.8. 로그로 남기지 말것

  • 함수 진입. 중요한 함수에 대해서만 기록할것. 또는 디버그 레벨로만 기록할것

  • 반복문 안의 데이터. 많은 반복을 가지는 데이터를 기록하지 말것. 작은 반복은 OK. 큰 반복에 대해서는 주기적으로 요약 형태로 기록

  • 큰 메시지나 파일 내용을 로그로 기록하지 말것. 디버깅을 위해 일부만 기록하거나 요약만 기록할것

  • 인자한 에러. 실제로는 오류가 아닌 오류. 읽는 사람을 혼란스럽게 할수 있음. 오류 처리가 정상 실행 경로의 일부일때 발생함

  • 반복적 에러: 동일하거나 유사한 로그를 반복적으로 기록하지 말것. 로그를 에러로 가득채우게 되며 실제 오류를 숨기게 됨. 에러 타입의 빈도는 로그 모니터링에 중요함.

2. Logging Best Practices

2.1. Logging Exception

다음중 예외를 정상적으로 기록하는 방법은 무엇일까요?

try {
...
}
catch(Exception ex){

  log.error(e);        //A

  log.error(e, e);        //B

  log.error("" + e);        //C

  log.error(e.toString());        //D

  log.error(e.getMessage());        //E

  log.error(null, e);        //F

  log.error("", e);        //G

  log.error("{}", e);        //H

  log.error("{}", e.getMessage());        //I

  log.error("Error reading configuration file: " + e);        //J

  log.error("Error reading configuration file: " + e.getMessage());        //K

  log.error("Error reading configuration file", e);        //L

}

G와 L 만이 정답입니다. A,B는 컴파일도 않되고 나머지는 정상적인 stack trace가 출력되지 않거나 잘못된 메시지가 나옵니다.

2.2. Tracking

Log Detail의 추가 정보를 참조 하세요

2.3. Logging Interface

외부 시스템과 인터페이스 하는 부분은 반드시 로그를 남겨야 합니다. 접속 정보, 수행에 소요된 시간, 수행 결과등이 포함 되어야 합니다.

2.4. Logging Cross-cut

하나의 작업을 위해 여러 클래스가 참여하지만, 해당 작업에 대한 로그를 모아서 봐야 할때는 별도의 독립된 이름을 가지는 Logger를 선언하여 같이 사용하세요

class Business1 {
  static final Logger log = Logger.getLogger("biz");
}

class Business2 {
  static final Logger log = Logger.getLogger("biz");
}

이렇게 설정한후에 logback.groovy에 별도 파일로 기록 되게 할수도 있습니다.

2.5. Override toString

일반적인 객체를 문자열과 합칠때 기본적으로는 Classname@hashcode 형태의 문자열로 치환됩니다. toString을 override 하여 객체의 내용을 추정할수 있도록 하는게 좋습니다.

많은 경우, 객체가 참조하고 있는 필드들의 내용을 죽 나열하는 형태로 작성하게 되는데요 Eclipse등 IDE에서 제공하는 코드 생성 기능을 이용하여도 좋지만, 이 경우 필드에 변화가 발생하면 잊지 않고 코드 생성을 다시 해야 합니다.

가급적이면 Lombok의 자동 코드 생성 기능을 이용하시면 됩니다.

@ToString
class Business1 {
  static final Logger log = Logger.getLogger("biz");
}


@Data  -> @ToString, @HashCode, @Getter @Setter
class Business1 {
  static final Logger log = Logger.getLogger("biz");
}

2.6. Logging entry/exit

개발할때 로그를 기록한다면 보통 "현재 실행중인 정보의 snapshop"을 남기기 위해 인자값이나 임시값을 로그로 남기는 경우가 많습니다. 하지만 프로그램이 실행되면 변수의 값 만큼 중요해지는 것이 프로그램의 흐름에 대한 정보입니다. 중요한 메소드에 대하여 메소드 시작 및 종료시에 해당 이벤트를 기록하는 것이 좋습니다.

3. Logging Anti-patterns

3.1. Avoid String Concat or Log4j style guard clause

로그 메시지를 남길때 인자값등을 남기고자 문자열을 합치는 구문을 만들때가 있습니다.

log.debug("Param:"+ param1+" Option:"+option);

문제는 debug나 trace 로그가 운영에서도 문자열을 합치기 위해 CPU와 메모리가 소비된다는 것입니다. 그래서 log4j 시절에는 다음과 같은 보호절(Guard clause)를 사용했습니다.

if(loger.isDebugEnabled()) {
  log.debug("Param:"+ param1+" Option:"+option);}

리소스 낭비 문제는 없어졌지만 로그 한줄 기록하고자 로직 코드가 복잡해졌습니다.

그래서 SLF4J에서는 다음과 같은 방법으로 기술하게 합니다.

log.debug("Param: {} Option: {}", param1, option);

3.2. Wrong Level

debug로 레벨이 지정되어야 하는 로그를 INFO로 기록하면 지나치게 많은로그를 남기게 됩니다. 또한 ERROR와 WARNING은 애매하기도 합니다. Logging Level에서 기술한 내용을 참고하세요 "2AM 규칙"이 여기에 적용됩니다. 이 로그가 발생하면 오전 2시에라도 일어나서 긴급 대응 해야 하는 것들은 "ERROR"로 기록해야 합니다

3.3. Avoid side-effect

로그를 기록하기 위해 호출하는 메소드중 부가 작용이 있는 것을 회피 해야 합니다.

log.debug("Param: {} Option: {}", param1.getValue(), option);

...

int getValue() {
  value ++;
  return value;
}

3.4. Avoid System.out

System.out.println 을 이용한 로그는 파일로 기록 되지 않으며, 그 순간에 보지 못하면 나중에 다시 볼수 없습니다. console application이 아닌이상 System.out은 사용하시면 안됩니다

3.5. Avoid Infinite loop

이런 코드는 toString을 호출하면 무한루프에 빠집니다 ㅠㅠ

class Node {
  String id;
  Node parent;
  List<Node> childs;
  public String toString() {
    return id+" parent:"+parent+" child:"+childs;
  }
}

3.6. Do not eat exception

이거 하지 마세요 ㅠㅠ

try {
...
}
catch(Exception ex) {}

최소한 로그에 기록이라도 해주세요

try {
...
}
catch(Exception ex) {
log.error(ex);
}

3.7. Missing Essential details

로그에 나중에 디버깅을 위해 필요한 중요한 정보를 누락한체 기록하면 오류가 발생한 이후에 추가 정보를 기록하게 수정하고 다시 배포 하고 디버깅하는 악순환을 반복해야 합니다.

예를들어 User Access denied 를 기록했는데 "어떤 유저"인지가 누락되면 어떻게 될까요? 아니면 인증 실패를 로그를 남기지 않으면 어떻게 될까요?

일반적으로 주요한 이벤트는 반드시 로깅하고, 실행이 어떻게 되는것인지 추적할수 있는 문맥정보들을 같이 기록해주시면 됩니다.

3.8. Avoid Security sensitive info

로그에 password를 기록하면 될까요? toString을 너무 의존하면 보안상 중요한 정보가 Flat file에 저장되어 버릴수 있다는 경각심을 항상 가져야 합니다.

Tags: logging  log  best practice  application logging