3.5.3 디버깅을 위한 로깅(logging)

자바를 처음 학습할 때 콘솔에 값을 출력하기 위한 용도로 사용하는 API가 System.out.pringln()이다. 아마도 대부분의 개발자가 자바를 처음 시작할 때 "Hello World" 메시지를 출력하면서 자바 학습을 시작하기 때문에 처음 접하는 API일 것이다. 그만큼 자바 개발자에게 친숙한 API이다.

개발자는 애플리케이션이 정상적으로 동작하는지 확인하기 위한 목적, 애플리케이션에 문제가 발생했을 때 원인을 파악하기 위한 디버깅을 목적으로 수많은 메시지를 출력한다. 메시지를 출력하기 위한 목적으로 System.out.println()을 사용하는 방법은 애플리케이션 성능을 저하시키는 원인이 된다. 웹 애플리케이션을 개발할 때 System.out.println()으로 디버깅 메시지를 출력하면 파일로 메시지가 출력하게 되는데 이 작업은 상당한 비용이 발생하는 작업이다. 때문에 애플리케이션을 배포하기 전 소스코드에 포함된 System.out.println()으로 구현한 코드를 삭제하거나 주석 처리하는 방법으로 해결하는 경우도 있었다. 하지만 이 또한 모두 비용이며, 디버깅을 목적으로 메시지를 출력하고 싶으면 또 다시 원복해야 하는 문제점이 있다.

이 같은 단점을 보완하기 위해 등장한 라이브러리가 로깅(logging) 라이브러리이다. 신입 개발자에게 처음으로 하는 조언 중의 하나가 지금까지 System.out.println()을 사용했다면 앞으로 이 API를 잊고, 로깅 라이브러리를 활용해 디버깅 메시지를 출력하는 습관을 들이라고 한다. 그만큼 로깅 라이브러리를 활용해 디버깅 메시지를 출력하는 습관을 가지는 것은 애플리케이션 성능에 중요하다. 아직까지 System.out.println()을 사용한다면 이번 기회에 로깅 라이브러리를 사용하는 습관으로 바꿀 것을 추천한다. 자바 진영에서 많이 사용하는 로깅 라이브러리는 Logback 이다. 과거에는 Log4J 라이브러리를 사용했지만 최근에는 더 좋은 성능의 Logback을 사용할 것을 추천한다. 자바 진영은 많은 로깅 라이브러리 구현체가 존재하는데, 더 좋은 구현체가 등장할 때마다 전체 소스코드에서 로깅 라이브러리 구현 부분을 수정하는 어려움이 있다. 이 어려움을 해소하기 위해 SLF4J라는 라이브러리를 활용해 로깅 API에 대한 창구를 일원화했다. 즉, 자바 소스코드는 SLF4J라는 라이브러리를 활용해 로깅 API에 대한 창구를 일원화했다. 즉 자바 소스코드는 SLF4J 라이브러리를 사용해 디버깅 메시지를 남기면 실제로 디버깅 메시지를 출력하는 구현체는 Log4J, Logback이 담당하는 방식으로 동작한다. 이와 같이 구현할 경우 추후 Logback보다 더 좋은 로깅 라이브러리가 등장할 경우 소스코드는 수정할 필요없이 구현체를 담당할 로깅 라이브러리만 교체하면 된다.

실습을 위해 세팅한 web-application-server 프로젝트의 RequestHandler에서 로깅 라이브러리를 사용한 부분을 살펴본다.

 

- RequestHandler.java

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class RequestHandler extends Thread {

    private static final Logger log = LoggerFactory.getLogger(RequestHandler.class);
    ...

    public void run() {
        log.debug("New Client Connect! Connected IP : {}, Port : {}", connection.getInetAddress(), connection.getPort());
        ...
    }

    ...

}

 

web-application-server 프로젝트는 로깅 구현체로 Logback 라이브러리를 사용하고 있다. 하지만 위 소스코드에서는 Logback 라이브러리를 직접 사용하지 않고 SLF4J를 사용하고 있다(import하는 부분을 보면 org.slf4j이다). Logback 라이브러리에 대한 구현체는 메이븐 설정 파일인 pom.xml에 설정하고 있다.

 

- pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
	<groupId>org.nhnnext</groupId>
	<artifactId>web-application-server</artifactId>
	<version>1.0</version>
	<packaging>jar</packaging>
    ...
	<dependencies>
		...
		<!-- logger -->
		<dependency>
			<groupId>ch.qos.logback</groupId>
			<artifactId>logback-classic</artifactId>
			<version>1.1.2</version>
		</dependency>
	</dependencies>
    ...
</project>

 

자바 진영의 로깅 라이브러리는 메시지 출력 여부를 로그 레벨을 통해 관리한다. 대표적인 로그 레벨은 TRACE, DEBUG, INFO, WARN, ERROR가 있으며, 로그 레벨은 TRACE < DEBUG < INFO < WARN < ERROR 순으로 높아진다. 로그 레벨이 높으면 높을수록 출력되는 메시지는 적어지고, 로그 레벨이 낮을수록 더 많은 로깅 레벨이 출력된다. 예를 들어 WARN 로그 레벨로 설정하면 WARN, ERROR 레벨의 메시지만 출력되고, DEBUG 로그 레벨로 설정하면 DEBUG, INFO, WARN, ERROR 레벨의 메시지가 출력된다.

각 메시지에 대한 로그 레벨은 로깅 메시지를 구현할 때 결정된다. RequestHandler의 log.debug()로 구현하면 DEBUG 로그 레벨이다. TRACE는 log.trace(), INFO는 log.info(), WARN은 log.warn(), ERROR은 log.error() 메서드를 사용하면 된다.

로그 메시지를 출력할 때 눈여겨 볼 부분 중의 하나는 메시지를 생성하는 부분이다. 로그 메시지를 출력할 경우 다음과 같이 메시지를 구현하는 것이 일반적이다.

 

log.debug("New Client Connect! Connected IP : " + connection.getInetAddress() + ", Port : " + connection.getPort());

 

그런데 위와 같이 구현할 경우 로그 레벨이 INFO, WARN인 경우 굳이 debug() 메서드에 인자를 전달하기 위해 문자열을 더하는 부분이 실행될 필요가 없다. 자바에서 문자열을 더하는 비용은 예상보다 큰데, 로깅 레벨이 높이 굳이 실행할 필요가 없음에도 불구하고 실행됨으로써 애플리케이션의 성능을 떨어트린다.

SLF4J는 이 같은 단점을 보완하기 위해 동적인 메시지를 구현하기 위한 별도의 메서드를 제공한다. 성능을 떨어트리지 않으면서 동적인 메시지를 구현하려면 다음과 같이 구현할 수 있다.

 

log.debug("New Client Connect! Connected IP : {}, Port : {}", connection.getInetAddress(), connection.getPort());

 

위와 같이 구현함으로써 debug() 메서드에서 로그 레벨에 따라 메시지를 더할 필요가 있는지의 여부를 판단하게 된다.

Logback의 로그 레벨과 메시지 형식에 대한 설정 파일은 logback.xml이다. web-application-server는 src/main/resources 디렉토리에서 logback.xml을 관리하고 있으며, 설정 내용은 다음과 같다.

 

- logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>
<configuration>
	<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
		<layout class="ch.qos.logback.classic.PatternLayout">
			<Pattern>%d{HH:mm:ss.SSS} [%-5level] [%thread] [%logger{36}] - %m%n</Pattern>
		</layout>
	</appender>
	
	<root level="DEBUG">
		<appender-ref ref="STDOUT" />
	</root>
</configuration>

 

로깅 라이브러리를 활용하면 출력한 로그 메시지의 패턴도 변경할 수 있다. 로그 메시지가 출력되는 시간, 스레드 이름, 로그 메시지가 출력되는 소스코드의 위치 등 다양한 패턴 조합을 위 설정 하나만 변경함으로써 설정 가능하다. 위 설정을 통해 출력된 로그 메시지는 다음과 같다.

 

19:51:34.396 [DEBUG] [Thread-9] [webserver.RequestHandler] - New Client Connect! Connected IP : /0:0:0:0:0:0:0:1, Port : 56078

 

위 설정의 로그 레벨은 DEBUG 이다. 보통 개발 단계에서는 DEBUG와 같이 낮은 로그 레벨로 설정하다 실 서비스로 배포할 때 INFO, WARN과 같은 로그 레벨로 설정함으로써 개발 단계에서 디버깅을 위해 출력하는 로그를 출력하지 않도록 설정한다.

로깅 라이브러리는 성능 좋은 애플리케이션을 개발하기 위해 반드시 학습하고 사용해야 할 라이브러리 중의 하나이다. 학습에 많은 시간을 투자하지 않아도 사용할 수 있으니 아직까지 사용하지 않았다면 반드시 사용할 것을 추천한다.

동영상을 통해 학습하는 것이 익숙하다면 다음 동영상을 활용해 학습한다.

 

https://youtu.be/TcKEGh7KShI : 로깅 라이브러리가 필요한 이유, 로깅 라이브러리 설정 방법에 대해 다룬다. 동영상의 모든 내용은 책에서 이미 다룬 내용이다.

 

https://youtu.be/040Y3MBNnyw : 로깅 레벨 설명, 패키지별 로깅 라이브러리 설정, 동적인 메시지 구현 시 주의할 점, 로깅을 위해 반복적으로 추가되는 설정을 이클립스 템플릿(template)으로 해결, 이클립스 formatter 설정 방법을 설명한다. 특히 로깅 메시지를 추가하기 위해 매번 반복적으로 구현해야 하는 코드를 이클립스 템플릿을 활용해 해결하는 방법은 반드시 익혀두면 좋다.

 

구글에서 "eclipse slf4j logger template"로 검색하면 Log4j, SLF4J 라이브러리별 템플릿을 찾을 수 있다. SLF4J 템플릿은 다음과 같이 추가하면 된다.

 

${:import(org.slf4j.Logger,org.slf4j.LoggerFactory)}
private static final Logger LOGGER = LoggerFactory.getLogger(${enclosing_type}.class);

이와 같이 단순 반복적으로 발생하는 코드를 템플릿 코드로 추가해 놓으면 개발 생산성을 높이는데 많은 도움을 받을 수 있다.


참고도서 : https://roadbook.co.kr/169

[신간안내] 자바 웹 프로그래밍 Next Step