kotlin-logging vs slf4j 뭘 사용해야 하지?

서론

최근 사내 프로젝트를 마이그레이션을 진행하면서 프로젝트를 재 설계 할 수 있는 기회가 생겼습니다.
아키텍처와 라이브러리를 선정하는 과정에서 발생한 logging 라이브러리의 버전 관리 문제점과 어떻게 해결을 하였는지를 공유하고자 합니다.
 

배경 지식

회사에서의 신규 프로젝트를 준비하면서 언어 플랫폼은 kotlin, 프레임워크는 스프링으로 채택되었습니다. 
그리고, 필요한 여러 외부 라이브러리에 대한 의존성을 주입하는 과정에서 로깅을 위한 두 개의 선택지가 존재했습니다.

• 스프링 진영에서 사용하고 있는 facade 형태로서 로깅을 처리할 수 있는 slf4j를 사용할 것 인가
• kotlin 위에서 유리하게 동작하는 kotlin-logging을 사용할 것 인가.

결론은, kotlin-logging을 사용하는 것으로 결정을 내렸는데, 그 이유는 다음과 같습니다.

• 기존의 다른 프로젝트에서도 kotlin-logging을 사용하고 있다. 기존 컨벤션을 따라가자.
• slf4j 에는 로깅 레벨에 따른 방어 코드가 없다면 의도치 않은 메모리 사용이 발생할 수 있다.

조금 생소한 두 번째 케이스가 어떤 상황인지 살펴보도록 하겠습니다.
 
평상시에 로그를 사용하는 경우에 대체적으로 로그 레벨을 info로 사용합니다. 단, 개발 환경에 따라서 로그 레벨을 debug or trace로 단계를 낮추어서 사용하는 경우가 있습니다. 예시 코드를 살펴보겠습니다.

public class Reader {

	private final FooCalculator fooCalculator;
	private final FooReader fooReader;
	
	public Reader(...) {
		...
	}

	public FooResponse read() {
		Foo foo = fooReader.read();
		Money fee = fooCalculator.calc(foo.fee, foo.feeVersion);
		log.debug("request[{}][{}] foo 계산 이후 금액 : {}", foo.fee, foo.feeVersion, fooCalculator.calc(foo.fee, foo.feeVersion));
		return FooResponse.from(foo, fee);
	}
}

함수를 또 호출했어야만 했는가. 에 대한 의문이 들테지만 마땅한 예시가 떠오르지 않았습니다. 단순 예시로만 봐주시길 바랍니다.
 
해당 로그를 봤을 때는 로그 레벨을 debug 이하로만 설정하지 않으면 해당 로그는 실행되지 않겠구나.라고 생각이 듭니다.
하지만, 작은 문제가 하나 있는데요. 실제로는 debug 내부에 메서드가 불 필요하게 호출되어 불 필요한 메모리를 소모할 수 있다는 것입니다. 위 케이스와 유사한 케이스가 하나 더 있는데요. 
 
바로 Optional의 orElse, orElseGet 입니다.

String name = Optional.of("example")
.orElse(method());

String name = Optional.of("example")
.orElseGet(() => method());

 
실제로 값이 있음에도 불구하고 orElse() 내의 method는 실행되지만 orElseGet()에서는 한 단계 action을 위임하여 메서드의 실행 순서를 지연시켜 불 필요한 메서드의 수행을 막고 있습니다.
 
자세한 예시는 https://www.baeldung.com/java-optional-or-else-vs-or-else-get에서 확인이 가능합니다.
이러한 문제를 알고 있기에 Logger 인터페이스에도 다음과 같은 퍼블릭 메서드들이 있습니다.

public interface Logger {

  public boolean isTraceEnabled();
  public boolean isDebugEnabled();
  public boolean ...
  
  ...
}

 
그럼 해당 퍼블릭 인터페이스를 사용하여 기존 코드를 수정하여 발생하지 않도록 수정해 보도록 하겠습니다.

public class Reader {

	private final FooCalculator fooCalculator;
	private final FooReader fooReader;
	
	public Reader(...) {
		...
	}

	public FooResponse read() {
		Foo foo = fooReader.read();
		Money fee = fooCalculator.calc(foo.fee, foo.feeVersion);
		if (log.isDebugEnabled) {
			log.debug("request[{}][{}]foo 계산 이후 금액 : {}", foo.fee, foo.feeVersion, fooCalculator.calc(foo.fee, foo.feeVersion));
		}
		return FooResponse.from(foo, fee);
	}
}

기존의 문제는 해소가 되었지만, 코드의 가독성이 상당히 떨어지는 문제가 생겼습니다. 비즈니스 적인 관점이 담긴 코드에 단지 로그만을 처리하기 위한 불 필요한 로직이 추가되었기 때문입니다. kotlin-logging에서는 위와 같은 상황을 인지하고 있었기에 로그를 람다로 호출할 수 있도록 정의해 두었습니다.

public interface KLogger : org.slf4j.Logger {
	public abstract fun debug(msg: () -> kotlin.Any?): kotlin.Unit
}

 
Optional에서 해결했던 방안과 동일하게 람다를 받아 불 필요한 메모리 사용을 하지 않도록 하였습니다. 트렌비의 사내 시니어 개발자분들은 위 문제를 알고 있었기에 기존 컨벤션을 Kotlin-Logging을 사용했던 것이 아닐까? 하고 추측도 해봤습니다.
 
로깅 라이브러리에 대한 선정이 완료되었으니 완성된 프로젝트의 구조를 살펴보도록 하겠습니다. 프로젝트의 구조는 멀티모듈 구조로 사용되며 공통으로 사용되는 모듈에 대해서는 따로 정의하여 모듈을 분리해 주었습니다. 그 구조는 다음과 같습니다.
 
root
ㄴ common-libs
  ㄴ logging
  ㄴ ...
 
하위의 logging을 사용해야 하는 별개의 모듈에서는 logging 모듈을 의존하여 로그를 사용합니다.

dependencies {
	implementation(project(":common-libs:logging"))
}

본론

이제 본격적으로 발생한 문제점에 대해서 살펴보도록 하겠습니다.

문제 상황

기존 사내 프로젝트들에서 kotlin-logging의 라이브러리 버전을 확인해 봤습니다. 기존 kotlin-logging은 다음과 같았습니다.

dependencies {
	dependencySet("io.github.microutils:2.1.23") { // 별도로 통합 Version 관리를 사용 중이나 설명을 위해 명시
        entry("kotlin-logging-jvm")
    }
}

로깅 라이브러리 버전이 더 좋은 버전으로 업데이트가 되었을 가능성이 있다고 생각하여 해당 라이브러리의 최신 버전을 확인해 봤습니다.

라이브러리 사진(1)

2023년 2월 1일 자로 마지막 업데이트가 되고, 현재는 다른 곳에서 새로 릴리즈 되고 있는 것을 볼 수 있었습니다.

라이브러리 사진(2)

글 작성 당시에는 7.0.0 버전까지 Release가 되었었는데, 현재는 7.0.3 버전까지도 활발하게 release 되고 있는 것을 볼 수 있습니다.
7.0.0 버전에 들어가서 추가해야 하는 내용을 확인해 보니 다음과 같습니다.

runtimeOnly("io.github.oshai:kotlin-logging-jvm:7.0.0")

runtimeOnly를 명시한 이유는 사용하는 입장에서는 사용할 수가 없는 것일 텐데 어디에 호환이 되어 있는 거지? implementation으로 바꿔서 넣자. 7.0.0 버전은 많은 사람들이 사용하고 있는 stable 한 버전이고 호환성에도 문제가 없겠지?

여기서부터가 파국의 시작이었습니다. 문제는 뒤로 하고 프로젝트 세팅을 이어 나가보겠습니다.
향후, 버전 관리를 유용하게 하기 위해 buildSrc/Versions에 version을 명시하도록 하겠습니다.

object Versions {
  const val kotlinLoggingVersion = "7.0.0"
}

이제, 아까 생성해 주었던 logging 모듈에 logging 라이브러리 의존성을 추가합니다.

dependencies {
	implemenation("io.github.oshai:kotlin-logging-jvm:${kotlinLoggingVersion}")
}

 

로깅 사용 추상화

자바에서는 @Slf4j 롬복을 사용하여 간편하게 로그를 사용할 수 있는 환경을 구축할 수 있었습니다. 만약, 롬복을 사용하지 않는다면 다음과 같은 정적 메서드를 통해서 로그를 생성하여야 했습니다.

private Logger log = LoggerFactory.getLogger("name");
// private static Logger log = LoggerFactory.getLogger(this.getClass());
// private static Logger log = LoggerFactory.getLogger(Foo.class);

kotlin 2.1 버전 이상에서는 롬복 호환성을 높여준다는 이야기가 있었지만, 아직 확실하지 않으니 기존에 시니어분들이 구축해 놓은 확장함수와 inline function, reified를 활용한 템플릿을 만들어서 사용해 보겠습니다. 확장함수, inline function, reified는 코틀린 문법이기 때문에 자세한 설명은 넘어가도록 하겠습니다.
 
Extensions.kt 코틀린 파일을 만들고 코드에 다음과 같은 내용을 추가해 주었습니다.

fun logger(name: String): KLogger = KotlinLogging.logger(name)

inline fun <reified T : Any> T.logger(): KLogger = logger(T::class.java.name)

그리고 이제 의존성을 추가해 준 모듈에 가서 log를 사용해 보도록 하겠습니다.

import com.bombo.template.logging.logger

class Foo {
  private val log = logger()
  
  ...
}

잘 동작하겠지?라는 생각과 달리 다음과 같은 에러를 마주하게 됩니다.

Cannot access class 'io. github. oshai. kotlinlogging. KLogger'. Check your module classpath for missing or conflicting dependencies.import com.bombo.template.logging.logger

모듈을 인식하지 못했다의 가능성은 배제하고.. 의존성이 충돌되었다는 얘기로 보입니다. 다른 데서 KotlinLogging에 대한 의존성이 추가된 부분이 있나? 하고 라이브러리 주입 상태를 확인해 봐도 보이지 않았습니다. runtimeOnly로 바꾸면 사용이 안될 텐데....라는 것을 알고 있지만 일단 바꿔봤습니다.

dependencies {
	runtimeOnly("io.github.oshai:kotlin-logging-jvm:${kotlinLoggingVersion}")
}

Unresolved reference 'KLogger'

당연하게도, 컴파일 시점에서는 Kotlin-logging의 존재 자체를 모르기 때문에 컴파일 에러가 발생합니다. 과거의 버전으로 돌아가야 하나? 하다가 Spring이 버전 관리를 잘해주고 있으니 Slf4 j와 log4j를 잘 활용하여 kotlin-logging 처럼 만들어보고자 하였습니다.

의도는 LoggerFactory를 통해 생성되는 log의 구현체를 Slf4j 라이브러리 내부에 kotlin-logging을 포함시켜서 만들어질 수 있도록 해야 할 것 같다는 생각이 드는데 방법을 찾지는 못하였습니다.

해결 방안

다시 로그 모듈로 돌아와 로그 모듈의 라이브러리 의존성을 변경해 줍니다. 기존의 slf4j의 라이브러리 모듈은 spring-plungin이 자체적으로 버전 관리를 해주고 있기 때문에 별도의 버전은 명시하지 않고, 기존 버전을 가져와서 사용합니다.

dependencies {
    implementation("org.slf4j:slf4j-api")
    implementation("ch.qos.logback:logback-classic")
}

slf4j를 사용할 때 주의해야 할 점은 "로깅 레벨에 따른 방어 코드가 없다면 의도치 않은 메모리 사용이 발생할 수 있다."입니다. 그렇다면 발생하지 않도록 Wrapper 클래스로 감싸서 해보는 건 어떨까? 하는 방안을 떠올리고 적용해 보겠습니다.
 
먼저, LoggerWrapper 클래스를 만들어주고 방어 코드를 추가 한 내부 코드를 작성해 줍니다. kotlin-logging을 사용하면 ErrorStackTrace 편리하게 노출시킬 수 있도록 다음과 같이 코드를 작성을 가능하도록 해두었습니다.

log.error(e) {"에러가 발생하였습니다."}

 
위와 똑같이 작성될 수 있도록 내부 구현체를 살펴보니 다음과 같은 구조로 되어있었습니다.

public fun error(throwable: Throwable?, message: () -> Any?): Unit =
    at(Level.ERROR) {
      this.message = message.toStringSafe()
      this.cause = throwable
    }

 
위와 유사하게 하고 객체에 대한 메시지와 cause는 객체로 따로 분리하지 않은 형태로 단순한 LoggerWrapper를 만들어보겠습니다.

package com.bombo.template.logging

import org.slf4j.Logger

class LoggerWrapper(
    private val logger: Logger
) {
    fun info(message: String) {
        if (logger.isInfoEnabled) {
            logger.info(message)
        }
    }

    fun info(callMessage: () -> Any?) {
        if (logger.isInfoEnabled) {
            logger.info(callMessage().toString())
        }
    }

    fun info(t: Throwable, callMessage: () -> Any?) {
        if (logger.isInfoEnabled) {
            logger.info(callMessage().toString(), t)
        }
    }

    fun debug(message: String) {
        if (logger.isDebugEnabled) {
            logger.debug(message)
        }
    }

    fun debug(callMessage: () -> Any?) {
        if (logger.isDebugEnabled) {
            logger.debug(callMessage().toString())
        }
    }

    fun debug(t: Throwable, callMessage: () -> Any?) {
        if (logger.isDebugEnabled) {
            logger.debug(callMessage().toString(), t)
        }
    }

    fun warn(message: String) {
        if (logger.isWarnEnabled) {
            logger.warn(message)
        }
    }

    fun warn(callMessage: () -> Any?) {
        if (logger.isWarnEnabled) {
            logger.warn(callMessage().toString())
        }
    }

    fun warn(t: Throwable, callMessage: () -> Any?) {
        if (logger.isWarnEnabled) {
            logger.warn(callMessage().toString(), t)
        }
    }

    fun error(message: String) {
        logger.error(message)
    }

    fun error(callMessage: () -> Any?) {
        logger.error(callMessage().toString())
    }

    fun error(t: Throwable, callMessage: () -> Any?) {
        logger.error(callMessage().toString(), t)
    }
}

총 3가지의 형태로 작성할 수 있도록 하였습니다. 기존의 자바 진영에서의 코드처럼 작성할 수 있도록 하는 방식, 람다로 작성 할 수 있도록 하는 방식입니다. 이제 Extentions 클래스를 수정해 주도록 하겠습니다.

package com.bombo.template.logging

import org.slf4j.LoggerFactory

fun logger(name: String): LoggerWrapper = LoggerWrapper(LoggerFactory.getLogger(name))

inline fun <reified T : Any> T.log(): LoggerWrapper = logger(T::class.java.name)

Slf4j의 LoggerFactory로 생성된 Logger 객체를 LoggerWrapper가 의존주입받아서 사용할 수 있도록 하였습니다. 실제 사용 지점으로 가서 테스트를 해보겠습니다.

@Transactional(readOnly = true)
@Service
class ExampleService(
    private val exampleRepository: ExampleRepository,
) : ExampleUseCase {

    private val log = log() // Extensions.log()

    @Transactional
    override fun update(command: ExampleUpdateCommand): ExampleDto {
        val example = exampleRepository.findById(command.id) ?: throw IllegalArgumentException("Example not found")
        example.changeName(command.name)

        log.debug { "example changeName : ${example.name}" }
        exampleRepository.save(example)

        return ExampleDto(example.name)
    }
}

다음과 같은 테스트용 서비스 로직을 작성하고, 테스트 코드를 작성해 보겠습니다.

class ExampleServiceTest : ApplicationContextTest() {

    @Test
    fun update() {
        // given
        val savedId = exampleRepository.save(Example.newInstance("테스트 명"))
        val updateCommand = ExampleUpdateCommand(savedId, "수정된 테스트 명")

        // when
        exampleService.update(updateCommand)
        val sut = exampleRepository.findById(savedId)

        // then
        Assertions.assertThat(sut?.name).isEqualTo("수정된 테스트 명")
    }
}

 

Debug log

Debug용 log가 정상적으로 출력됨을 확인할 수 있습니다.

결론

프로젝트를 만들어가는 과정에서 예상치 못한 로그 버전 관리로 인해 로깅 라이브러리를 개선하는 여정을 작성해 봤습니다.
생각보다 정말 많은 부분을 스프링 진영에서 해결을 해주고 있었다는 것을 새삼 느낄 수 있는 기간이었습니다. 예전에 토비님 영상에서 옛날에는 스프링 버전마다 호환 가능한 라이브러리 버전을 엑셀로 정리해 두었다하시며 보여주신 적이 있는데 정말 힘들었겠구나 싶었습니다..
 
글을 작성하다가 kotlin-logging 공식문서가 아닌 스프링 공식 문서에서 logging 부분을 다시 살펴봤는데 다음과 같은 글을 볼 수 있었습니다.

스프링 공식문서

이전에 말했던 모듈을 교체할 수 있는 방법이 명시가 되어있더군요... 위에서 언급했던 모듈 교체를 다음과 같이 했다면 runtimeOnly로 대체 가능하지 않았을까 하는 생각은 드는데 잘 되는지 테스트를 해볼 필요는 있을 것 같습니다.
 
긴 글 읽어주셔서 감사합니다.
 
해당 작성 글에 대한 코드는 https://github.com/bombo-dev/template/tree/main/kotlin에서 확인이 가능합니다.
질문 및 피드백은 언제나 환영합니다!