log 알고 한 번 찍어보자

Grafana와 Loki를 통해 에러 로그들을 살펴보며 일을 하던중

로그, 대체 어떻게 찍히고 쌓이는 걸까 하는 의문점이 생겼다

이번에 로그를 한 번 제대로 찍어보겠다 📸

(차근 차근 기본적으로 로그를 찍는 것부터 최종적으로 Grafana 및 Loki를 도입하는 것까지 천천히 알아볼 것이다.)

---

1. 로그란?

IT 에서 로그는 발생되는 행위와 이벤트 정보를 시간에 따라 남겨둔 데이터 라고 정의할 수 있다.

개발자는 이 로그들을 통해서 모니터링 (응답 시간, 이벤트 발생 여부 확인 등), 디버깅 및 문제 해결, 접속 기록을 통한 보안 및 감시의 역할을 수행해 낼 수 있다.

---

2. Slf4j

@Slf4j 는 한 번쯤 보았을 것이다.

Slf4j 는 Simple Logging Facade For Java 의 약자이다.

그 이름처럼, @Slf4j는 Lombok 라이브러리에서 제공하는 어노테이션으로, 다양한 로깅 프레임워크 (ex : java.util.logging , logback, log4j) 에 대한 단순한 추상화를 제공하여 사용자가 배포 시 원하는 로깅 프레임워크를 선택하여 사용할 수 있게 한다.

만약 로링 프레임워크를 logback 이 아닌 log4j 로 바꿔야 하는 상황이면 log를 쓴 클래스마다 import 문을 수정해야 할 것이다.
하지만 Slf4j를 사용한다면, 우리는 각 클래스별 로깅에 대한 import 를 Slf4j에 의존하기 때문에 코드 수정 없이 원하는 로깅 프레임워크로 의존성을 바꾸면 된다.

참고로 여기서 의존성을 바꾼다는 말은,
Slf4j 가 실행할 때 클래스패스에 있는 로깅 라이브러리 (ex logback, log4j 등)를 찾아 바인딩하기 때문에 나온 것이다.

요약하자면 Slf4j 는 로깅에 있어서 상위 계층을 추상화하고 하위 구현체를 실행시점에 유연하게 결합할 수 있게한, 의존성 역전 원칙을 잘 지킨 객체지향적 구조라는 것이다.

+) Spring Boot 에서는 보통 Logback 이 기본적으로 사용된다고 한다.

---

3. 직접 로그 사용해보기

스프링부트 프로젝트를 간단하게 생성해 보았다.

build.gradle에 보면 아래와 같이 의존성이 추가되어 있다.

dependencies {
	implementation 'org.springframework.boot:spring-boot-starter-web'
	compileOnly 'org.projectlombok:lombok'
	developmentOnly 'org.springframework.boot:spring-boot-devtools'
	annotationProcessor 'org.springframework.boot:spring-boot-configuration-processor'
	annotationProcessor 'org.projectlombok:lombok'
	testImplementation 'org.springframework.boot:spring-boot-starter-test'
	testRuntimeOnly 'org.junit.platform:junit-platform-launcher'
}

여기에 Slf4j가 어디에 있을까?
org.springframework.boot:spring-boot-starter-web 안에 있는 org.springframework.boot:spring-boot-starter에 포함되어 있다.
자세히 알고 싶으면 아래 구조를 참조하면 된다.

spring-boot-starter
 └── spring-boot-starter-logging
      ├── slf4j-api
      ├── logback-classic
      ├── logback-core
      ├── jul-to-slf4j
      ├── jakarta.annotation-api

로그를 바로 사용할 수 있다는 것을 알게 되었으니 한 번 사용해 보겠다. 😎

간단하게 api 하나를 만들어 주었다.

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.time.LocalDateTime;

@RestController
@Slf4j
public class Controller {

    @GetMapping("/")
    public void controllerA(){
        log.info(LocalDateTime.now() +" controllerA start");
        log.info(LocalDateTime.now() +" controllerA end");
    }
}

@Slf4j가 무엇인지는 앞서 설명을 했고, @Slf4j 어노테이션을 붙여주면 log 객체를 바로 사용할 수가 있다.
@Slf4j가 클래스에 적용되면 Lombok 이 알아서 private static final Logger log = LoggerFactory.getLogger(MyService.class); 와 같은 코드를 자동으로 생성해주기 때문이다.

api에 요청이 들어오면 요청 시간과 어떤 api가 실행되었는지 + 끝나는 시간을 찍어 로그로 찍어보았다.
프로젝트를 실행시키고 api 요청을 보내면 아래와 같이 콘솔에 로그가 찍힌다.

음.. 내 의도대로 찍히지 않는다. 앞에 것들을 수정하고 싶다. 한 번 바꿔 보겠다.

3.1 Log Pattern 커스텀하기

Spring boot 는 기본적으로 로그 구현체로 logback 을 사용하고,
logback의 경우 log Pattern 을 따로 정의하지 않으면 defaults.xml 에 설정되어 있는 대로 로그를 찍어준다.

	<property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}){} %clr(${PID:-}){magenta} %clr(--- %esb(){APPLICATION_NAME}%esb{APPLICATION_GROUP}[%15.15t] ${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
	<property name="CONSOLE_LOG_CHARSET" value="${CONSOLE_LOG_CHARSET:-${file.encoding:-UTF-8}}"/>
	<property name="CONSOLE_LOG_THRESHOLD" value="${CONSOLE_LOG_THRESHOLD:-TRACE}"/>
	<property name="CONSOLE_LOG_STRUCTURED_FORMAT" value="${CONSOLE_LOG_STRUCTURED_FORMAT:-}"/>

defaults.xml 에 로그 형식이 위와 처럼 되어 있을 것이다.
간단하게 표로 정리해 보았다.

표현	설명
${}	환경 변수 또는 설정 값 참조
:-	값이 없을 때 기본값 사용
CONSOLE_LOG_PATTERN	로그 형식 정의
CONSOLE_LOG_THRESHOLD	최소 로그 레벨 설정
CONSOLE_LOG_CHARSET	문자 인코딩 설정
CONSOLE_LOG_STRUCTURED_FORMAT	구조화된 로그 포맷 사용 설정 (JSON 등 구조화된 로그를 원하면 설정하면 됨

주요 변환 단어

변환 단어	설명	예제 출력
%d	날짜와 시간	2025-03-06 14:30:12
%p 또는 %level	로그 레벨	INFO, DEBUG
%t 또는 %thread	실행된 스레드 이름	main, worker-1
%c 또는 %logger	로거의 이름 (패키지 포함)	com.example.MyClass
%C	클래스명 (FQCN)	com.example.MyClass
%M	실행된 메서드 이름	executeTask
%L	코드의 실행 라인 번호	42
%F	실행된 파일명	MyClass.java
%msg 또는 %m	로그 메시지	Application started
%n	줄바꿈 문자 (플랫폼별)	\n 또는 \r\n

자 이제 내가 원하는 형식으로 Pattern을 만들어보겠다.
Pattern 은 application.yml 혹은 logback-spring.xml 에 설정하면 된다.
참고로 logback-spring.xml 이 application.yml 보다 더 우선된다.
logback-spring.xml 은 application.yml과 같이 resources 폴더 하위에 위치시키면 된다.

<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level %logger{36}  ❤ - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

날짜, 로그 레벨 (왼쪽 정렬, 최소 5글자) , 클래스명 (최대 36글자) 하트 이모지 - 로그 메시지의 형식으로 pattern을 커스텀 하였다.

+더 자세히 살펴보기
appender 의 종류에는 ConsoleAppender ( 콘솔에 출력함 ) , FileAppender (로그를 파일에 저장할 수 있음 ) , RollingFileAppender (일정 시간마다 새로운 로그 파일을 생성함) 등이 있다.
appender 는 name 을 지정할 수 있으며, appender-ref 에 사용하고 싶은 appender 의 name 을 넣으면 된다.
level 은 info , debug 등 자신이 보고싶은 로그 레벨까지로 설정하면 된다.

이렇게 설정하면 콘솔에는 아래 화면과 같이 로그가 찍힌다.

변경된 로그 패턴이 잘 적용되었는지 구분하기 위해 하트를 넣었는데 생각보다 로그가 많이 이뻐졌다.

이제 로그 패턴을 이용해서 날짜를 넣을 수 있는 것을 확인했으니, 앞선 코드의 로그에서 날짜를 찍어주었던 부분들을 삭제하면 될 것 같다.

@RestController
@Slf4j
public class Controller {

    @GetMapping("/")
    public void controllerA() throws Exception {
        log.info(" controllerA start");
        log.info(" controllerA end");
        throw new IOException();
    }
}

이번에는 exception 을 한 번 만들어보았다.
콘솔에 로그가 어떻게 찍히는지 한 번 보자.

음. 별로 마음에 들지 않는다.
누가 요청을 했는지 로그에 찍으면 좋을 것 같다. 나쁜 놈이 일부러 내 프로젝트 방해하려고 올 수도 있지 않겠는가.
또한 api 요청마다 start 와 end 지점을 로그로 찍을 것인데 요청이 올 때마다 자동으로 로그가 찍힌다면 내가 많이 편할 것 같다.

이 부분들을 추가 해 보자.

3.2 Interceptor 를 이용해 로그 자동으로 찍기

요청이 올 때마다 로그가 찍혔으면 좋겠다.
그런데 내가 api 메소드 하나하나마다 로그를 찍는 것은 힘들 것 같다.

이 고민은 Interceptor , AOP , Filter 를 통해 해소할 수 있다.

Interceptor 는 컨트롤러 전 후 로깅이 필요할 때 적합하다.
preHandle, postHandle, afterCompletion 등을 이용해 메소드별로 처리가 가능한데 다만 컨트롤러로 들어오는 요청만 국한되어 사용할 수 있어 사용 범위가 좁다.

Filter 는 모든 요청/응답에 대해 로깅을 할 수 있고, 특히 인증과 관련해서 보안 관련 처리하기에 좋다. 다만 요청을 가로채기 때문에 로깅 후 특정 데이터 변경이 어렵다.

AOP 는 특정 메소드 호출 전 후 로깅을 처리할 때 적합하다. 서비스 레이어까지 포함해서 상세하게 로깅을 컨트롤할 수 있는데 그런 만큼 설정이 다른 것에 비해 복잡하게 느껴질 수 있다.

Interceptor, AOP, Filter 에 대해서는 더 자세히 공부하는 것을 추천하며,
현재 컨트롤러 요청에 대해서만 로깅이 하고 싶기에 Interceptor 방식으로 로깅을 구현해 보겠다.

먼저 HandlerInterceptor 을 구현할 클래스를 생성한다.

package com.log.loggy.interceptor;

import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.springframework.lang.Nullable;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

@Slf4j
public class LogInterceptor implements HandlerInterceptor{

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        log.info("controller start");
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable ModelAndView modelAndView) throws Exception {
        log.info("controller end");
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable Exception ex) throws Exception {
        if( ex != null){
            log.error("error 발생 😥" );
        }
    }
}

preHandle 은 컨트롤러 호출 전에 호출된다. return 값이 true 면 다음 인터셉터/컨트롤러를 호출하고 false 면 더이상 진행하지 않는다.

postHandle 은 컨트롤러 호출 후에 호출된다. 컨트롤러에서 예외가 발생하면 호출되지 않는다.

afterCompletion 은 뷰가 렌더링 된 이후에 호출된다. 컨트롤러에서 예외가 발생하여도 호출이 된다. 요청 완료 후 정리할 작업을 수행하거나 예외 발생 여부 확인 후 추가처리를 위해 사용한다.

가볍게 코드를 작성해 만든 interceptor 를 등록해 보겠다.
WebMvcConfigurer interface 를 구현할 클래스를 생성한다.
@Configuration 어노테이션을 붙여주고 만들어둔 interceptor 를 등록한다.

import com.log.loggy.interceptor.LogInterceptor;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

@Configuration
public class WebConfig implements WebMvcConfigurer {
    
    @Override
    public void addInterceptors(InterceptorRegistry registry){
        registry.addInterceptor(new LogInterceptor())
                .addPathPatterns("/**" ) //특정 패턴만 적용되도록
                .excludePathPatterns("/exclude/**"); //제외할 경로
    }
}

이제 앞서 클래스에서 찍었던 로그를 지우고 api 에 요청을 보내보겠다.

자, 이렇게 했더니 이제 요청이 올때마다 로그를 하나하나 찍어야 했던 문제가 사라졌다.
그런데 실행 클래스가 모두 interceptor.LogInterceptor 로 찍혀 어느 api 가 실행되었는지 확인하기가 어려워졌다.

이제 이 문제를 해결하면서 요청자도 로그로 찍도록 해 보겠다.

    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String handlerInfo = "";

        //실행된 컨트롤러  + 메서드명 가져오기
        if (handler instanceof HandlerMethod) {
            HandlerMethod method = (HandlerMethod) handler;
            handlerInfo = method.getBeanType().getSimpleName() + "." + method.getMethod().getName();
            MDC.put("handler", handlerInfo);
        }

        //요청자 정보 가져오기
        String ip = request.getRemoteAddr();

        log.info("start (사용자 {})", ip);
        return true;
    }

preHandle을 수정하였다.
HandlerMethod를 이용해 실행된 컨트롤러와 메서드명을 가져오고, HttpServletRequest 를 이용해 요청자 ip 주소를 가져왔다.

컨트롤러와 메서드명은 MDC 를 이용해 기존 로그 패턴에 추가하여 사용할 수 있게 하였고,
사용자 주소는 기본 log.info 를 통해 넣어주었다.

조금더 알아가기 : MDC란? ⭐️
MDC는 Slf4j , LogBack , Log4j 등 다양한 로깅 프레임워크가 지원하는데, 로깅 시스템과 통합되어 쓰레드 단위로 key-value 형식으로 데이터를 읽고 쓸 수 있는 기능이다.
쓰레드 단위로 동작하기 때문에 다중 사용자 환경에서 하나의 요청 흐름을 로그로 나타내기 적합하다. (ex: requestId 을 MDC에 저장하고 이를 로그에 찍어주면 한 개의 요청 흐름을 분명히 추적할 수 있게 됨)
다만 비동기 환경에서는 값이 제대로 전달되지 않으니 개발자가 직접 전달하거나 MdcRunnable 과 같은 유틸 클래스 사용 등을 하여 문제를 해결해야 한다.
MDC를 이용하면 쓰레드 단위로 저장한 데이터를 로그 패턴에 바로 넣을 수 있어 편리하게 로그를 남길 수 있다.
LogBack의 MDC에 대해 더 자세히 알고 싶다면 공식 문서 를 보면 좋을 것 같다. 그리고 MDC 는 threadLocal 기반인데 threadLocal 에 대해 궁금하다면 threadLocal posting 을 간단히 보아도 좋을 것 같다.

MDC에 저장한 값을 꺼내 사용할 수 있도록 로그 패턴은 아래와 같이 수정하였다.

  <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level %logger{36}  %X{handler} ❤ - %msg%n</pattern>

%X 는 주입받을 값이 없으면 나타내지 않는다는 뜻이다.
%X{handler} 를 추가하여 MDC에 넘겨준 값을 받을 것이다.

이제 실행 해 보겠다.

의도대로 잘 실행이 되었다.

Exception을 상속받아 비즈니스 Exception 을 생성하여
error log 를 관리하는 방법도 추가하면 좋겠지만 현재 포스팅에 조금 벗어난 주제인 것 같다.
그 내용은 다른 포스팅에 작성하고 우선은 여기까지만 해 보도록 하겠다.

미약한 내용이지만 누군가에게 조그마한 도움이 되면 좋겠다.

---

참조
SLF4J 공식 문서
SPRING BOOT 문서 중 로깅
LogBack 문서 중 Layouts