라이브러리의 로그가 왜 안 찍힐까

이슈

• B 서비스에서 공용 라이브러리에서 찍는 로그가 안 찍히는 현상이 있었다.
• A 서비스에서는 동일한 공용 라이브러리를 사용하고, 로그도 정상적으로 찍히고 있어서 B 서비스에도 동일하게 적용을 했던 것인데
• B 서비스에서는 로그가 찍히지 않아서 자세히 살펴보기 시작했다.

문제의 발단

공용 라이브러리에서 slf4j Logger를 사용하여 로깅을 하는 부분이 있었다. 간단하게 나타내면 아래와 같다.

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

public abstract class FileBasedUpdater {
	private static final Logger logger = LoggerFactory.getLogger(FileBasedUpdater.class);
	
	public void update() {
		// ...
		logger.error("No files to update, lastUpdatedAt: {}", lastUpdatedAt);
		// ...
    }
}

그런데 테스트 중에 해당 로그가 찍히지 않는 것을 확인했고, 문제의 원인을 찾기 시작했다.

문제의 원인

다행히 애플리케이션 구동 시점에 slf4j에서 아래와 같은 warning을 띄워주는 것을 확인했다.

SLF4J(W): No SLF4J providers were found.
SLF4J(W): Defaulting to no-operation (NOP) logger implementation
SLF4J(W): See https://www.slf4j.org/codes.html#noProviders for further details.

Warning 메시지나 링크에서 친절하게 설명이 되어 있듯이,
결국 slf4j에 호환되는 provider(slf4j의 구현체)가 없어서 디폴트인 NOPLogger(아무것도 하지 않는 slf4j의 구현체)가 바인딩된 것이다.
위 메시지에서 안내한 공식 문서 링크에도 아래와 같이 명시되어 있다.

In the absence of a provider, SLF4J will default to a no-operation (NOP) logger provider.

그런데 구현체가 없는 게 이상하다. 구현체가 없었다면 그동안 계속 문제가 됐을텐데..?
다행히도 이것도 역시 slf4j에서 친절하게 아래와 같은 warning 메시지를 띄워준다.

SLF4J(W): Class path contains SLF4J bindings targeting slf4j-api versions 1.7.x or earlier.
SLF4J(W): Ignoring binding found at [jar:file:/WEB-INF/lib/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J(W): Ignoring binding found at [jar:file:/WEB-INF/lib/log4j-slf4j-impl-2.17.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J(W): See https://www.slf4j.org/codes.html#ignoredBindings for an explanation.

구현체가 있으나(slf4j-log4j12와 log4j-slf4j-impl), slf4j-api 1.7.x 이하 버전에만 호환되는 구현체여서 바인딩되지 않고 무시됐다는 것이다.
안내한 문서를 읽어보면 아래와 같이 명시되어 있다.

Earlier versions of SLF4J relied on the static binder mechanism which is no longer honored by slf4j-api version 2.0.x. In case SLF4J 2.x finds no providers targeting SLF4J 2.x but finds instead bindings targeting SLF4J 1.7 or earlier, it will list the bindings it finds but otherwise will ignore them.

결국 slf4j 2.x 버전부터 바인딩 메커니즘이 변경됐고, slf4j 구버전(1.7.x 이하 버전)의 바인딩 메커니즘만 호환되는 구현체(provider)들은 무시된다는 내용이다.

그래서 slf4j-api의 버전을 확인해보았다.
아니나 다를까, 패키지 안에 slf4j-api-2.1.0-alpha1.jar 가 포함되어 있다.

여기까지 확인한 결과, 로그가 안 찍히는 직접적인 원인을 확인했다.
slf4j-api 2.x 버전이 포함되었고, 호환되는 구현체가 없어서 디폴트 구현체인 NOP logger로 바인딩되면서 로그가 안찍힌 것이다.

그럼 무엇이 slf4j-api 2.x 버전이 포함되도록 만들었을까?

의존성 관리를 위해 maven을 사용하고 있으므로, pom.xml 파일을 살펴보았다.
탑 레벨에 명시적으로 slf4j-api를 포함하고 있진 않았고, 아래와 같이 transitive dependency로 포함되어 있었다.
아래는 Intellij의 dependency analyzer의 결과이다.

위 결과를 보면 알 수 있듯이, common-Y에 의해 2.1.0-alpha1이 채택되었음을 알 수 있다.
여기서 참고로 common-X와 common-Y의 slf4j-api 관련 의존성은 아래와 같다.

<!-- common-X의 pom.xml 일부 -->
<dependency>
	<groupId>org.slf4j</groupId>  
    <artifactId>slf4j-api</artifactId>  
    <version>1.7.25</version>  
</dependency>

<!-- common-Y의 pom.xml 일부 -->
<dependency>
	<groupId>org.slf4j</groupId>  
	<artifactId>slf4j-api</artifactId>  
	<version>[1.7.36,)</version>  
</dependency>

common-X는 1.7.25 버전을 정확히 명시하고 있고, common-Y는 1.7.36 이상 버전을 명시하고 있다.

그럼 결국, maven에서 “1.7.25” 버전과 “[1.7.36, )” 버전의 충돌을 해결한 결과, “[1.7.36, )”을 채택하였고, 결과적으로 2.1.0-alpha1이 채택되었다고 추론할 수 있다.
참고로 2.1.0-alpha1은 2025년 3월 15일 기준 최신버전이다.

요약하면, common-Y의 transitive dependency에 의해 slf4j-api 2.x 버전이 채택된 것이다.

그런데 A 서비스에서는 왜 됐을까?

아래는 A 프로젝트의 dependency analyzer 결과이다.

놀랍게도 B 프로젝트와 의존성이 완전히 동일한데, B 프로젝트와 달리 A 프로젝트에서는 1.7.25 버전이 채택된 것이다.
실제로 패키지에도 slf4j-api-1.7.25.jar가 포함되어 있었다.

common-X와 common-Y가 동일하게 경쟁하는데, B 프로젝트에서는 common-Y가 승리하고, A 프로젝트에서는 common-X가 승리하는 것이 의아했다.

동일한 의존성인데 마지막으로 채택된(effective) 의존성이 다르니, 처음에는 maven 버전 차이(각각 3.5.0과 3.9.5를 사용하고 있었다.)를 의심했으나,
maven의 충돌 해결 방식이 변경되었다는 내용을 딱히 찾을 수가 없었고, 동일한 메이저 버전에서 충돌 해결 로직이 바뀔 것 같진 않아서 일단 가능성을 배제해두었다.

하지만, 결론부터 이야기하면, 동일한 의존성인줄 알았지만 다른 의존성을 명시하고 있었다.
A 프로젝트에는 parent pom을 포함하고 있었고, B 프로젝트에는 parent pom이 포함되어 있지 않았다.
그리고 이 차이로 인해 최종적으로 채택되는(effective) slf4j-api 의 버전이 달라졌다.

parent pom의 존재

parent pom은 말그대로 pom을 상속하기 위한 목적으로 존재한다. 여러 개의 child pom에서 일관된 의존성을 참조하고자 할때 유용하게 사용될 수 있다.
실제로 A 프로젝트에는 아래와 같은 parent pom을 포함하고 있었다.

<!-- A 프로젝트의 pom.xml 일부 -->
<parent>  
    <groupId>org.springframework.boot</groupId>  
    <artifactId>spring-boot-starter-parent</artifactId>  
    <version>1.5.15.RELEASE</version>  
    <relativePath/> 
</parent>

그리고 이 spring-boot-starter-parent을 따라가다보니,
spring-boot-starter-parent는 다시 spring-boot-dependencies를 parent로 가지고,
spring-boot-dependencies 를 보니 아래와 같이 slf4j-api의 버전이 1.7.25로 명시되어 있음을 확인할 수 있다.

<!-- spring-boot-dependencies의 pom.xml 일부 -->
<dependencyManagement>
	<dependencies>
		<dependency>  
		    <groupId>org.slf4j</groupId>  
		    <artifactId>slf4j-api</artifactId>  
		    <version>${slf4j.version}</version>  
		</dependency>
	<dependencies>
<dependencyManagement>

<properties>
	<slf4j.version>1.7.25</slf4j.version>
</properties>

• spring-boot/spring-boot-dependencies/pom.xml at v1.5.15.RELEASE · spring-projects/spring-boot · GitHub

parent pom에 명시된 내용은 탑 레벨 pom에 선언한 것과 동일한 효과를 갖기 때문에, A 프로젝트의 pom.xml에 slf4j-api 의 버전을 1.7.25 으로 명시한 것과 동일한 효과를 발생시킨다.

이 차이를 발견하기 어려웠던 이유는, dependencyManagement에 의해 결정된 버전은 dependency analyzer에는 표현이 되지 않기 때문이다. (maven dependency plugin의 dependency:tree 수행 결과 역시 표현이 안되기는 마찬가지이다.
이는 버그라기보다, dependencyManagement 자체가 jar를 실제로 포함하는 개념이 아니라, “jar가 포함이 된다면 이 버전으로 통일해”의 개념에 가깝기 때문이다.

A와 B의 차이가 발생한 이유

결국 지금까지 살펴본 내용을 종합해보면

• A 프로젝트 : slf4j-api 1.7.25 채택
  • A 프로젝트의 slf4j-api의 버전이 1.7.25로 채택된 것은 spring-boot-starter-parent를 parent pom으로 가지면서, 이 parent pom에서 명시적으로 버전을 1.7.25로 지정했기 때문에 채택된 것이며,
  • common-X 과 common-Y의 의존성과는 아예 무관한 것이었다.
• B 프로젝트 : slf4j-api 2.1.0-alpha1 채택
  • 반면 B 프로젝트에서는 탑 레벨(parent 포함)에 slf4j-api의 버전을 따로 명시하지 않았기 때문에
  • common-X와 common-Y의 transitive dependency로서 서로 경쟁하면서
  • common-Y의 의존성이 승리하면서 최신 버전(2.1.0-alpha1)이 채택되었던 것이다.

해결방안

그럼 원인이 명확하게 확인되었으니, 어떻게 하면 로그를 찍을 수 있을지 해결 방안에 대해 고민해보아야한다.

slf4j-api 2.x 버전 사용

어쨌든 프로젝트 B에서 slf4j-api 2.x 버전이 포함되면서 문제가 되고 있는 상황이다.
그럼 첫번째로 생각할 수 있는 방법은 slf4j-api 2.x 버전을 정상적으로 사용할 수 있도록 하면 된다.
slf4j 구현체를 slf4j-api 2.x 버전과 호환되는 버전으로 올려주면, 해당 구현체로 바인딩되면서 로그가 안 찍히는 문제는 해결은 될 것이다.
실제로 위에서 언급한 문서에서도 해당 이슈가 발생한 경우 구현체 버전을 올리라고 가이드하고 있다.

그러나 이 해결책은 결론적으로 아래와 같은 이유로 기각하였다.

• slf4j-api 2.x 버전을 채택하게 된 것이 의도된 것이 아니고, 사실 의도치 않게 실수로 채택된 것이다.
• 그리고 slf4j-api 중 활용하는 API는 모두 1.x 버전의 API이며, 2.x 버전에만 존재하는 API (fluent logging API 등) 를 전혀 활용하지 않는다.
• A 프로젝트에서도 slf4j-api 를 1.x 버전을 사용하고 있으므로, 2.x 버전을 꼭 써야하는 게 아니라면 굳이 버전을 다르게 가져갈 필요가 없다.

slf4j-api 1.x 버전 유지 (dependencyManagement 활용)

그럼 slf4j-api 를 1.x 버전으로 유지하면서 해결할 수 있는 방법을 모색해보자.
결국 B 프로젝트의 pom을 A 프로젝트와 동일하게 만든다면, 동일한 slf4j-api 1.7.25 버전을 가져갈 수 있을 것이다.

가장 간단하게는 A 프로젝트에서처럼 spring-boot-starter-parent를 동일하게 parent로 지정하는 방법을 선택할 수 있으나,
그러면 spring-boot-starter-parent에 포함된 수많은 의존성 버전들이 의도치 않게 고정되면서 더 큰 후폭풍을 맞이할 수 있으니 적합하지 않다고 판단했다.

결국 달성하고자 하는 목적은 slf4j-api의 버전만 명시적으로 지정하고 싶은 것이므로,
spring-boot-starter-parent 에서 slf4j-api의 버전을 명시한 것과 동일한 방식(depedencyManagement 방식)으로 프로젝트 B의 pom에도 반영해주면 된다.

실제 depedencyManagement를 반영한 결과는 아래와 같다.

<!-- B 프로젝트의 pom.xml 일부 --> 
<dependencyManagement>
	<dependencies>
		<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>slf4j-api</artifactId>
			<version>1.7.25</version>
		</dependency>
	</dependencies>
</dependencyManagement>

위 내용을 반영하여 패키징한 결과, 프로젝트 B에 대해서도 1.7.25 버전이 채택되었다!

그리고 최초의 목적대로 로그가 기록된 것 또한 확인할 수 있다.

이후의 multiple binding 문제

위에서 로그가 찍히는 것까지 확인했으니, 최초의 목적을 달성했다.
그러나 이번에는 slf4j에서 새로운 warning을 띄운다.

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/WEB-INF/lib/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/WEB-INF/lib/log4j-slf4j-impl-2.17.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]

이번에는 slf4j의 provider가 여러 개여서 warning을 띄운다.

메시지에 명시된 문서에는 아래와 같이 나와있다.

SLF4J API is designed to bind with one and only one underlying logging framework at a time. If more than one binding is present on the class path, SLF4J will emit a warning, listing the location of those bindings.
When multiple bindings are available on the class path, select one and only one binding you wish to use, and remove the other bindings.

결국 slf4j는 단일 provider만을 사용하도록 설계되었기 때문에, 클래스 패스 내 provider가 여러 개일때 slf4j는 그 중에 하나를 선택한다는 내용이다.
프로젝트 B의 경우에는 org.slf4j.impl.Log4jLoggerFactory 가 채택됐다고 알려준다.
org.slf4j.impl.Log4jLoggerFactory는 org.slf4j:slf4j-log4j12 jar에 포함된 구현체이며, 이는 log4j 1.2 버전과 slf4j API의 브릿지 역할을 하는 jar이다.

프로젝트 B에서는 log4j 1점대 버전이 아닌, log4j2를 사용하고자 하였으므로,
org.slf4j.impl.Log4jLoggerFactory 가 아닌,
org.apache.logging.slf4j.Log4jLoggerFactory (org.apache.logging.log4j:log4j-slf4j-impl jar 내 포함) 가 바인딩되도록 해야한다.

물론, slf4j에서 임의로 채택한 구현체가 우연히 일치했다고 하더라도, 위 문서에서 가이드한 것처럼 사용하지 않는 구현체는 명시적으로 제외해주는 것이 바람직할 것이다.

따라서, org.slf4j:slf4j-log4j12 jar를 명시적으로 제외해주기 위해, 누가 이 의존성을 넣어주는지 확인해보았다.
확인 결과, org.apache.zookeeper:zookeeper에 의해 포함되고 있었다.

따라서 아래와 같이 org.apache.zookeeper:zookeeper에서 org.slf4j:slf4j-log4j12 를 명시적으로 제외함으로써 multiple binding 이슈를 해결하였다.

<!-- 프로젝트 B의 pom.xml 일부 -->
<dependency>
	<groupId>org.apache.zookeeper</groupId>
	<artifactId>zookeeper</artifactId>
	<version>3.4.9</version>
	<exclusions>
		<exclusion>
			<groupId>org.slf4j</groupId>
			<artifactId>slf4j-log4j12</artifactId>
		</exclusion>
	</exclusions>
</dependency>

결론

• slf4j-api 2.x 버전부터 바인딩 메커니즘이 변경되었으며, 구현체 버전이 변경된 바인딩 메커니즘을 지원하지 않으면 NOP logger가 채택되어 로그가 찍히지 않을 수 있으니 주의하자.
• 프로젝트 내 의존성이 실제로 어떻게 포함되는지 정확히 알고 사용할 필요가 있다.
  • 그렇지 않으면 의도치 않은 의존성이 포함되어 버그를 발생시킬 수 있다.

References

• Introduction to the Dependency Mechanism – Maven
• SLF4J Error Codes
• NOPLogger (SLF4J javadoc)
• spring-boot/spring-boot-dependencies/pom.xml at v1.5.15.RELEASE · spring-projects/spring-boot · GitHub
• Maven Repository: org.slf4j » slf4j-api
• SLF4J Manual