LOG MASTERING

LOG MASTERING

What is Log ?

로그는 가장 단순하게 추상화된 저장소이며, Append-only 만 가능하고, 전체 이벤트가 시간 순서대로 정렬된 자료구조를 의미한다.

2022-12-22 01:18:07.315 DEBUG 22340 --- [connection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn5: url=jdbc:h2:mem:testdb user=SA
2022-12-22 01:18:08.080 DEBUG 22340 --- [connection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection conn2: url=jdbc:h2:mem:testdb user=SA: (connection has passed maxLifetime)
2022-12-22 01:18:08.156 DEBUG 22340 --- [pool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0)

로그는 어떤(what) 이벤트가 언제(when) 발생했는지에 대한 시간순으로 정렬 된 기록이다.

Why Important Log ?

서비스 애플리케이션을 운영하면서 Logging 보다 중요한게 몇개나 있을까? 아마 Logging 이 가장 중요하다고 말해도 전혀 이상하지 않다.

모든 소프트웨어는 완벽하지 않다. 아마존 부사장인 버너 보겔스(Werner Vogels)는 소프트웨어는 모두 실패한다라고 말한바 있다. 실패에 빠르게 대응할 수 있도록 설계해야 한다는 말이다. 이를 Fault Tolerance 이라고 한다. 특히 우리 소프트웨어는 Network 를 사용하므로 네트워크 순단 상태에서의 대응도 중요하다. 관련해서 Strategies for Handling Network Blips; Ensuring Resilience in Distributed Systems 를 살펴보면 좋다.

내결함성(fault tolerance)를 높여도 분명 장애가 발생하는 순간이 있을 것이다. 장애가 발생했을때 언제, 어떤 이유에 의해서 장애가 발생했는지 추적(Trace)을 해야하고, 논리적인 근거를 바탕으로 해결책을 모색 해야하는데, 이 근거가 되는 것이 바로 Log 이다.

얼마만큼 로깅을 해야할까? 기본적으로 요청과 응답에 대해서는 무조건적으로 로깅해야 하며, @Service, @Component 등의 어노테이션을 사용한 클래스의 메서드의 요청, 응답도 로깅하는 것이 좋다.

Distributed Systems

Distributed Systems 에서 로그를 추적하고 모니터링 하는 활동을 Distributed Tracing 이라고 한다. Tracer 를 구현하기 위한 CNCF(Cloud Native Computing Foundation) 에서 구현한 비공식 표준이 The OpenTracing Semantic Specification 이다. 비공식 표준 문서를 보면 꽤나 분산 환경에서의 로깅에 대해서 많이 알게될 것이다.

Mapped Diagnostic Context

멀티 스레드 환경에서 요청을 처리하는 동안 내내 공통적으로 들고 다녀야 하는 값이 있을 수 있다. 이때 사용되는 기술이 MDC(Mapped Diagnostic Context) 이다.

Levels

Log Levels:

debug 는 주로 디버깅하다가 상세 정보를 로깅해야할 필요가 있을때 사용한다. info 는 주요 이벤트와 같은 필수 정보 전달을 위해서 로깅한다. warn 은 타 서버 API 와 연동시 타 서버에서 에러가 발생하여, 비지니스 로직이 실패하는 경우에 주로 사용한다. error 는 심각한 오류가 발생했을때 사용한다. INTERNAL_SERVER_ERROR 예외가 발생하는 경우 대부분 error 로그도 같이 남기는 것이 좋다. 특히 error 로그는 Incidents Alert 을 구성할때 판단되는 필수적인 요소이기도 하다. 특히 시스템의 가용성을 파악하기 위한 핵심 지표인 SLI(Service Level Indicators) 를 설정할 때 error rate(http 요청에 대한 http status 5xx 의 비율) 와 latency 등을 기준으로 하기 때문에 심각한 에러가 아님에도 불구하고 error level 을 남발하면 무수한 Incidents Alert 을 받게될 것이다.

Formats

Standard Fields:

Logback JSON Encoder 를 사용할 때 위 필드들은 따로 명시하지 않아도 LoggingEvent 에 탐지된다.

일반적으로 아래 포맷은 Default 로 가져가는 것이 좋다. (dd 는 Datadog 을 사용하는 경우)

{
  "@timestamp":"2022-11-28T09:55:26.482+09:00",
  "@version": "1",
  "message": "{ JSON 형식의 메시지 }",
  "logger_name": "org.hoxy.backend.server.core.logging.CustomConsoleAppender",
  "thread_name":"Worker",
  "level":"INFO",
  "level_value":20000,
  "dd.span_id":"0",
  "dd.trace_id":"0"
}

Kotlin 과 LoggerFactory 를 사용하는 경우 inline 으로 간편하게 사용할 수 있다.

inline fun <reified T> T.logger(): Logger {
    return LoggerFactory.getLogger(T::class.java)
}

class UserService {
    private val log = logger()
    // ...
}

We can customize the format by using LoggingEventCompositeJsonEncoder as the encoder instead of LogstashEncoder, as they provide greater flexibility in the JSON format. LoggingEventCompositeJsonEncoder 를 사용하면 <providers> 구문을 지원하는데 LogstashEncoder 보다 조금더 유연하게 customize 할 수 있다. 요즘은 대부분 LoggingEventCompositeJsonEncoder 를 사용한다.

Database Logging

Hibernate 를 사용하는 경우 Log 남기기

Masking Sensitive Data

Masking 작업을 진행하기 전에 가장 먼저 해야할 것은 Defining Problems 이다. 사실 모든 작업의 시작은 '문제 정의' 부터 시작된다.

요청/응답 시 민감정보가 마스킹 되어야 한다.
Interceptor 같은 기능이 필요하다. 로그를 찍을때, 실제로 로그를 출력하기 전에 Intercept 하여 마스킹 처리를 하면 좋을 것이다.
중첩 구조에서도 마스킹 처리가 가능해야 한다.
다양한 필드와 다양한 로그 포맷에 대해 마스킹 처리를 해야하므로 별도의 유틸 클래스가 필요하다.

기본적으로 아래와 같은 로그 포맷에 대해서 처리가 가능해야 한다.

/**
 * "pin":"12345"
 * "pin" : "12345"
 * "pinNumber":"12345"
 * "pinNumber" : "12345"
 * pin=12345
 * pin = 12345
 * pinNumber=12345
 * pinNumber = 12345
 */

여기서 기능 구현에 가장 도움이 되는 핵심적인 아이디어는 Intercept 이다. Logback 의 ValueMasker 를 구현한 구현체를 만들고 logback.xml 파일에 구현체를 설정하면 로그를 출력하기 전에 가로채서 마스킹 처리가 가능하다.

logback.xml:

...
<appender name="JSON_APPENDER" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <jsonGeneratorDecorator class="net.logstash.logback.mask.MaskingJsonGeneratorDecorator">
            <valueMasker class="org.hoxy.common.config.logging.SensitiveValueMasker">
                <path>$.message</path>
            </valueMasker>
        </jsonGeneratorDecorator>
        <providers>
            ...
        </providers>
    </encoder>
</appender>

<root level="INFO">
<springProfile name="local">
    <appender-ref ref="CONSOLE"/>
</springProfile>
<springProfile name="develop, real">
    <appender-ref ref="JSON_APPENDER"/>
</springProfile>
</root>
...

Implementation ValueMasker:

class SensitiveValueMasker : ValueMasker {
    override fun mask(context: JsonStreamContext, value: Any?): Any? {
        return if (value is String) { Masker.masking(value) } else { value }
    }
}

Masker:

object Makser {
    
    private const val MASKING_FORMAT = "*****"
    private val regEx = Regex("""(?:(?<!\w)|(?<="))(pin|vin|password|phone)\w*"?\s*[:=]\s*"?([\w-]+)"?""")

    fun masking(raw: String): String {
        return if (raw.contains(regEx)) {
            raw.replace(regEx) { matchResult -> matchResult.value.replace(matchResult.groupValues[2], MASKING_FORMAT) }
        } else { raw }
    }
}

Outputs:

"message":"MaskingResult = Sensitive(data=SensitiveData(vinNumber=*****, pin=*****, pinNumber=*****))"
"message": ... Sensitive: {\"sensitiveData\":{\"vinNumber\":\"*****\",\"pin\":\"*****\", \"pinNumber\":\"*****\"}}"

Links: