시작하며
안녕하세요. 카카오페이 <머니 클랜>에서 카카오페이 머니를 비롯한 전사 서비스에서 이용하는 금융플랫폼의 서버 개발을 하고 있는 Heli, 헬리입니다. 개발을 하다 보면 정말 많은 라이브러리와 프레임워크를 사용하게 됩니다. 그중에서는 이미 여러 번 사용 경험이 있는 기술도 있지만 그렇지 않은, 이번에 처음 사용해 보는 것들도 있기 마련입니다. 이번 글에서는 처음 사용해 보는 기술을 이용해 회사 업무를 진행하다 오픈소스에 기여하게 된 경험을 이제 만 1년 정도 된 주니어 서버 개발자의 입장에서 얘기해보고자 합니다.
💼 오픈소스 기여의 출발점: 신규 프로젝트
이번 오픈소스 기여는 신규 프로젝트 개발 환경을 구성하면서 시작되었습니다. 새롭게 진행하게 된 프로젝트에서는 기존에 전혀 사용해 본 적 없거나 적극적인 사용 경험이 없는 기술 스택을 사용하게 되어서 팀 내에 개발 환경 구성 등 참고할 만한 레퍼런스가 없는 상황이었습니다.
해당하는 기술 스택은 크게 두 가지(Kafka, MongoDB)였고, 아래와 같은 이유로 채택하게 되었습니다.
-
Kafka 타 조직/서비스에서 발행해 주는 이벤트를 구독(Subscribe)하고, 조직 내 서비스 서버 간 통신을 위해 사용
-
MongoDB 기존 프로젝트에 비해 데이터 간 연관관계가 복잡하지 않고, 모든 요청의 처리가 non-blocking I/O로 이루어져 사용
조직 내 기존 프로젝트들의 경우 은행과 직접 통신하며 금전을 다루는 프로젝트이다 보니 거래가 성공적으로 처리되었는지 검증하고 데이터를 갱신하는 일련의 과정 중 많은 부분이 blocking I/O로 이루어져 있었습니다. 하지만 신규 프로젝트의 경우 모든 요청이 실행 후 무시(Fire-and-Forget)
패턴에 기반하고 있어 non-blocking I/O 방식으로 풀어내는 것이 유리할 것으로 판단하였고 이를 지원하는 기술을 선택하게 되었습니다.
위와 같은 이유로 선택하게 된 Kafka, MongoDB 2가지 기술 중 MongoDB를 프로젝트에 적용하며, 문제점을 발견하고 개선안을 제안하는 것으로 시작된 오픈소스 기여 경험을 전달하겠습니다.
🤔 새로운 기술 사용
당연하게도 새로운 기술을 적용하는 과정이 순탄하지만은 않았습니다. MongoDB의 커넥션 풀 크기나 수명을 비롯해 여러 가지 옵션을 어떻게 설정해야 운영상 이슈가 없을지 팀 내에 경험이 전무한 상황이었기 때문입니다. 이러한 이유로 저희는 공식 문서와 MongoDB의 내부 구현을 짚어가며 프로젝트를 세팅하기 시작했습니다. 해당 프로젝트는 Kotlin(1.6.21)과 SpringBoot(2.7.3) 기반이었기 때문에 MongoDB와 통신하는 목적으로 스프링 클라우드에서 제공하는 spring-data-mongodb
/ spring-data-mongodb-reactive
를 선택할 수 있었습니다. 그리고 이 둘을 이용하여 커넥션 풀을 설정하는 경우 다음과 같은 옵션이 제공됩니다.
- 최소 커넥션 풀 크기: 5
- 커넥션 풀 최대 유휴 시간: 10초
- 커넥션 풀 최대 수명: 10초
// 스프링 의존 없이 직접 실행 가능한 예제 첨부
val client = MongoClients.create(
MongoClientSettings.builder()
.applyToConnectionPoolSettings { builder: ConnectionPoolSettings.Builder ->
builder.minSize(5) // 최소 커넥션 풀 크기: 5
builder.maxConnectionIdleTime(10000, TimeUnit.MILLISECONDS) // 커넥션 풀 최대 유휴 시간: 10초
builder.maxConnectionLifeTime(10000, TimeUnit.MILLISECONDS) // 커넥션 풀 최대 수명: 10초
}
.build())
Thread.sleep(Long.MAX_VALUE)
🚨 문제 발견
위와 같이 MongoDB 클라이언트 옵션을 설정하고 애플리케이션을 실행해 보면 1분마다 새로운 커넥션이 수립되었다는 INFO 로그가 발생하는 것을 볼 수 있습니다.
13:07:45.623 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:8, serverValue:247}] to 127.0.0.1:27017
13:07:45.666 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:9, serverValue:248}] to 127.0.0.1:27017
13:07:45.713 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:10, serverValue:249}] to 127.0.0.1:27017
13:07:45.752 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:11, serverValue:250}] to 127.0.0.1:27017
13:07:45.793 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:12, serverValue:251}] to 127.0.0.1:27017
...
13:08:45.625 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:13, serverValue:252}] to 127.0.0.1:27017
13:08:45.677 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:14, serverValue:253}] to 127.0.0.1:27017
13:08:45.714 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:15, serverValue:254}] to 127.0.0.1:27017
13:08:45.751 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:16, serverValue:255}] to 127.0.0.1:27017
13:08:45.786 [MaintenanceTimer-2-thread-1] INFO org.mongodb.driver.connection - Opened connection [connectionId{localValue:17, serverValue:256}] to 127.0.0.1:27017
🤮 애플리케이션 로그 오염
이는 상황에 따라 별일이 아닐 수도 있겠지만, 저희에겐 큰 문제였습니다. 저희는 애플리케이션의 로그 레벨을 5단계로 구분하고 그중에서 레벨이 INFO 이상인 로그들은 파일
에 기록하고 있었기 때문입니다.
- Log level: TRACE < DEBUG < INFO < WARN < ERROR
이대로라면 3개의 호스트로 구성된 MongoDB 클러스터에서 각 호스트의 최소 커넥션 풀 크기를 20으로 설정하는 경우 1분마다 60개의 INFO 로그가 발생하게 됩니다. 저희는 아무리 생각해 보아도 ‘이게 최선일까? 이게 맞는 방법일까?‘라는 의문이 들었고, 여기서 명확하게 추론할 수 있는 1분 주기
에 대해 고민해보게 됩니다. 분명 커넥션 풀을 설정할 때에 1분이라는 숫자는 어디에서도 등장하지 않았기 때문입니다. 이제 저희는 본격적으로 1분 주기
를 찾기 위한 MongoDB 내부의 구현을 살펴보기 시작합니다.
🧪 원인 분석 및 발견
spring-data-mongodb
시리즈는 커넥션 풀을 수립하고 관리하기 위한 목적으로 mongo-java-driver
Repository의 mongodb-driver-core
모듈을 사용하고 있습니다.
해당 모듈 내부에는 여러 세부 역할을 담당하는 클래스가 정말 많이 존재합니다. 그중에서 저희가 참고하고자 하는 커넥션 풀 설정과 관련된 부분은 ConnectionPoolSettings.java
에서 담당을 하고 있습니다. ConnectionPoolSettings
클래스를 조금 더 살펴보면, 저희가 앞서 설정했던 커넥션 풀 옵션 관련 필드와 빌더 메서드 등이 포함되어 있음을 확인할 수 있습니다.
JavaDoc: Class ConnectionPoolSettings
혹시 다들 눈치채셨나요? 저희는 여기서 1분마다
새로운 연결을 수립하는 원인을 발견할 수 있었습니다. 바로 maintenanceInitialDelayMS
/ maintenanceFrequencyMS
입니다. 필드의 이름만 보더라도 일정 주기로 maintenance
라는 행위를 할 것 같다는 느낌이 듭니다. 설레는 마음으로 해당 필드의 기본 값을 확인해 보면..?
이제 저희는 1분마다 백그라운드로 동작하는 무언가(maintenance
)가 있다는 사실을 알게 되었습니다. 그럼 이 maintenance
는 정확히 무슨 작업을 하고 있는 걸까요? 처음에는 MongoDB 클러스터 내 호스트의 상태를 주기적으로 체크하는 Heartbeat
같은 작업이라고 유추하였습니다. 하지만 내부 코드를 조금 더 살펴보니 Heartbeat
관련된 부분은 ServerMonitor->DefaultServerMonitor
에서 담당하고 있음을 확인할 수 있었습니다.
‘Heartbeat가 아니라면 어떤 행동일까?‘라는 생각을 가진 채 내부 구현을 조금 더 살펴보던 중 BackgroundMaintenanceManager
클래스를 발견하게 됩니다.
해당 클래스는 백그라운드에서 스케줄링하며 실행되는, 일종의 데몬을 생성하고 내부에서 maintenance
행위를 수행하도록 하는 클래스였습니다. 드디어 maintenance
의 정체를 알게 되었습니다. maintenance
를 실제로 수행하는 것으로 유추되는 doMaintenance
메서드에는 아래와 같은 주석과 함께 SDAM
이라는 키워드가 적혀있었습니다.
Synchronously prune idle connections and ensure the minimum pool size.
유휴 커넥션을 모두 정리하고, 최소 커넥션 풀의 크기를 확인하여 부족분 만큼 커넥션을 생성하는 행위가 maintenance
라고 합니다. 결국 부족분에 해당하는 커넥션을 생성하는 과정이 INFO 로그로 남게 되었던 것입니다.
🛠 해결책 도출
원인을 알아냈으니 이제 해결할 차례입니다.
해결책 1. maintenance 행위 중단
처음 접근했던 해결책은 정말 단순했습니다. 더 이상 maintenance 행위를 하지 않도록 하면 지금 겪는 문제를 해결할 수 있지 않을까라는 생각이었습니다. 그러나 이런 기능이 기본적으로 동작하는 것은 어떠한 이유가 있을 것 같다는 의심을 멈출 수 없었고, 주석과 함께 적혀있던 SDAM
이라는 키워드도 계속 아른거렸습니다.
하지만 정보를 찾는 것이 쉽지는 않았습니다. 결국 사내 인프라플랫폼팀의 MongoDB DBA 분에게 도움을 요청했고, SDAM(Server Discovery and Monitoring)에 대한 정보와 자료를 얻을 수 있었습니다. (to. 잭슨 감사합니다 🙇 )
간단하게 요약하자면, SDAM은 분산 환경에 구성된 토폴로지 속에서 각 컴포넌트가 토폴로지에 대한 최신 정보를 받아 가고 모니터링하는 행위라고 볼 수 있습니다. 만약 이러한 행위를 중단한다면 토폴로지 내의 특정 서버에 장애가 발생하여 다른 서버로 교체되었더라도 관련된 정보를 갱신할 수 없게 되는 것입니다. 단순하게 생각했던 첫 번째 해결책은 절대 실천해서는 안 되는 방법이었습니다.
해결책 2. log level 변경
처음 생각했던 해결책이 무산되고 해결하려는 문제
가 무엇인지 다시 한번 고민해 보았습니다. 그 결과 애플리케이션 로그가 오염되는 문제
가 궁극적으로 해결하고자 하는 문제라는 걸 깨달을 수 있었고, 로그 레벨만 INFO에서 DEBUG로 바꾸어 해결할 수 있을 것 같다는 느낌이 들었습니다.
그리하여 로깅을 수행하는 부분을 확인해 보았는데, (당연하게도) 임의로 로그 레벨을 변경할 수 없는 구조로 되어 있었습니다.
해결책 3. log tracing level 변경
로깅하는 그 순간의 로그 레벨을 변경할 수 없다면 애플리케이션 로그 파일에 작성되는 로그의 최소 레벨(트레이싱 레벨; tracing level)을 변경하는 방법도 존재합니다. 앞서 저희는 5단계의 로그 레벨 중, INFO 이상의 로그에 대해서 애플리케이션 로그 파일에 기록하고 있다고 이야기 드렸습니다.
- Log level: TRACE < DEBUG < INFO < WARN < ERROR
그렇기에 해당 부분에서 사용 중인 로거(org.mongodb.driver.connection
)의 트레이싱 레벨을 WARN으로 바꾸면 더 이상 INFO 레벨의 로그는 파일에 기록되지 않게 됩니다.
<logger name="org.mongodb.driver.connection" level="WARN" additivity="false">
<appender-ref ref="APPLICATION_FILE"/>
<appender-ref ref="CONSOLE"/>
<appender-ref ref="SENTRY"/>
</logger>
이 경우 정말로 필요한 INFO 레벨의 로그를 기록할 수 없다는 문제점이 존재합니다. 하지만 해당 로거를 사용하여 INFO 레벨로 로그를 기록하는 경우가 지금 문제되고 있는 단 하나의 케이스만 존재하였기에 이슈 없겠다 판단하고 관련 설정을 적용하였습니다. 최종적으로는 이 해결책을 적용해 1분 주기로 maintenance
하며 INFO 레벨 로그를 남겨 애플리케이션 로그를 오염시키는 문제를 해결할 수 있었습니다.
MongoDB에 개선안 제안
하지만 조금 이상합니다. 분명 Maintenance라는 행위는 유휴 커넥션 풀을 모두 정리(prune; close)하고, 새로운 커넥션 풀을 만드는 행위였습니다.
Synchronously prune idle connections and ensure the minimum pool size.
여기서 두 가지 의문이 들었습니다.
- 왜 새로운 커넥션 풀을 만들 때만 INFO 레벨로 로그를 남기는가?
- 왜 기존 커넥션 풀을 정리할 때에는 INFO 레벨로 로그를 남기지 않는가?
- 로그를 아예 안 남기는가? 혹은 다른 레벨로 남기는가?
이를 확인하기 위해 관련된 코드 블록을 찾아가 보았습니다.
😮 Not INFO 레벨
그렇습니다. 커넥션 풀을 만드는 행위를 제외하고선 모든 것들이 DEBUG 혹은 TRACE 정도의 레벨로 로깅이 되고 있었습니다. 더욱 이상했습니다.
🙋 왜?
이해가 안 됐습니다. 왜 이것만 INFO 레벨로 로깅을 하는 걸까? 팀원들과 이야기를 해보더라도 전혀 감이 잡히지 않았습니다.
결국 저희는 이 코드를 작성한 사람에게 물어보자.
라는 결론을 내리게 됩니다.
1. 로그 레벨이 INFO인 것이 버그인지? 혹은 의도한 것인지?
2. 해당 INFO 로그를 무시하기 위해 <해결책 3>을 적용하였는데, 더 나은 방법이 있을지?
두 내용을 담은 질문을 작성하였고, 정말 빠르게 답변을 받을 수 있었습니다.
1. INFO 로그 레벨은 의도한 것이다.
2. 이와 관련된 문의는 지금까지 단 한 번도 없었다.
3. <해결책 3>이 최선이다.
답변을 받기는 했는데, 그래도 이해가 안 됐습니다. 커넥션 풀을 정리할 때에는 DEBUG, 생성할 때에는 INFO. 왜 이렇게 하는지에 대한 당위성
을 전혀 공감할 수 없었습니다. 그리하여 제가 생각하는 보다 합리적인 당위성을 가지고, 제안을 하게 됩니다.
Change the “Opened connection …” log message from INFO to DEBUG.
Justification: it’s the only remaining connection-related log message that is logged at INFO (e.g. the connection-closed message is logged at DEBUG).
커넥션과 관련된 로그 메시지 중 유일하게 INFO 레벨이며 아무리 생각해 보아도 INFO 레벨을 유지할 필요성이 없는 것 같다. 만약 이 의견에 공감한다면 DEBUG 레벨로 변경하는 것을 고려해달라는 내용이었습니다.
🙆🏼 개선안 승낙
다행히 mongo-java-driver
의 메인테이너는 해당 제안에 공감을 해주었고, 제안했던 부분을 직접 수정하고 PR 올릴 수 있는 기회까지 제공해 주었습니다.
최종적으로 PR이 Merge 되었고, 해당 변경 사항은 다음 마이너 릴리즈인 4.8버전에 포함될 예정입니다.
마치며
회사 업무에서 시작된 이번 오픈소스 기여 경험은 저에게 매우 새로 자극이 되었습니다. 과거에는 회사는 단순히 일만 하는 공간이고, 개인과 회사의 성장 방향성이 일치하는 건 불가능하다고 생각했기 때문인데요. 얼마나 재미있던지, 그 이후로도 평소에 사용하고 있는 몇몇 오픈소스 프로젝트에 더 나은 코드 제안, 오타 수정 등 작은 규모의 변경 제안을 꾸준히 하게 되었습니다.
이번 경험을 통해 무엇을 하든 스스로 당위성
을 제시하기 위해 더욱 노력하게 되었습니다. 그리고 개발은 원래도 좋아했지만 앞으로 더 재미있게, 나아가 회사 업무 자체도 즐기며 할 수 있게 된 것 같습니다.
이번 <주니어 개발자의 오픈소스 활동 이야기>는 여기서 마무리하지만, 앞으로 더욱 다양한 활동을 하며 후속편으로 인사드리겠습니다!