운영 로그의 99.8%가 SQL 덤프

장애가 나면 Datadog에서 로그를 뒤집니다. 그런데 어느 날 특정 서비스의 로그를 열었더니 이런 줄이 화면을 가득 채우고 있었습니다.

Hibernate: select cardevice0_.`car_device_id` as car_devi1_19_, ... 
from `car_device` cardevice0_ where cardevice0_.`car_attachment_id`=?

 궁금해서 그 서비스의 하루치를 집계해 봤습니다. 한 gRPC 서버가 24시간 동안 남긴 로그 216,462건 중 Hibernate: 로 시작하는 SQL 덤프가 216,031건, 99.8% 였습니다. 실제 애플리케이션 로그는 431건이었습니다. 이 21만 건의 덤프는 1년 반쯤 전 기능 개발 커밋에 섞여 들어간 show-sql: true 한 줄이 프로파일 구분 없이 운영까지 흘러간 결과였습니다.

 

 포맷 문제도 있었습니다. 위 로그는 Datadog에 통짜 문자열 하나로 들어갑니다. 파싱된 필드가 없으니 "ERROR만", "이 클래스만" 같은 필터가 안 되고, 예외가 나면 스택트레이스 40줄이 40개의 개별 로그로 쪼개집니다. APM 트레이스 화면과 로그 화면은 서로를 모르는 남남이라, 장애 때는 타임스탬프를 눈대중으로 맞춰가며 오갔습니다.

 

팀에는 이미 답이 하나 있었습니다. 한 서버가 지난 5월부터 쓰고 있던 ECS JSON 로깅입니다. ECS JSON: 로그 한 줄 = JSON 객체 하나입니다. ECS는 Elastic Common Schema의 약자입니다. 로그를 JSON으로 찍되 필드 이름을 log.level, service.name, error.stack_trace 처럼 공개 표준에 맞추는 방식이고, logback에는 Elastic이 만든 인코더(co.elastic.logging:logback-ecs-encoder)를 붙이면 됩니다. 애플리케이션 코드는 한 줄도 바뀌지 않습니다. 같은 로그가 전환 전과 후에 이렇게 달라집니다.

전:

2026-08-22 16:39:03.583 INFO 1 --- [http-nio-8080-exec-1] k.s.c.CarWreckerCallRegisterService : 긴출 접수 시도: ...

후:

{"@timestamp":"2026-08-22T07:39:03.583Z","log.level":"INFO",
 "message":"긴출 접수 시도: ...",
 "service.name":"car-internal-api",
 "service.environment":"prod",
 "log.logger":"kr...CarService",
 "dd.trace_id":"f3fe864d8edd4b83...","dd.span_id":"3737263189..."}

Datadog이 JSON을 자동 파싱하므로 모든 키가 검색 가능한 필드가 됩니다. dd.trace_id 는 Datadog 자바 트레이서(dd-trace-java)가 MDC로 넣어 주는 값이라, APM 스팬에서 "이 요청의 로그 보기"는 클릭 한 번이면 됩니다. 스택트레이스는 error.stack_trace 필드 하나에 통째로 들어갑니다.

여기까지는 교과서 내용입니다. 이 글의 나머지는 이 표준을 17개 레포에 펼치면서 밟은 함정들입니다.

 

전수 조사: 상태 세 가지

먼저 팀의 JVM 레포 17개, 실행 가능한 앱 모듈 49개의 로깅 설정을 전부 조사했습니다. 결과는 세 부류로 갈렸습니다.

• 미적용. 대다수였습니다. logback 설정 파일이 아예 없거나 사람이 읽는 텍스트 패턴이었고, Spring Boot 2.5부터 3.2까지 걸쳐 있었습니다.
• 이미 적용. 레포 두 곳과 모듈 한 곳이 표준 원본과 같은 XML 방식을 쓰고 있었습니다. 인코더는 그대로 두었지만, 이 중 두 곳에서 뒤에 나올 함정 2의 버그가 발견돼 교정 대상이 됐습니다.
• 더 나은 방식으로 적용. Spring Boot 3.4부터는 XML 없이 logging.structured.format.console: ecs 한 줄로 내장 지원됩니다(2024년 8월 spring.io 공지). 최신 레포 둘은 이미 이걸 쓰고 있었습니다.

 실제로 게이트웨이 서비스에 XML 표준을 적용했다가, 운영 로그를 확인하고 되돌렸습니다. 이 서비스는 이미 Boot 내장 방식으로 ECS 8.11 스키마의 JSON을 내보내고 있었는데, 우리 XML 템플릿의 인코더는 ECS 1.2 기준입니다(Boot 내장 포맷은 ECS 8.11을 따르지만, logback-ecs-encoder 라이브러리는 ECS 1.2.0에 머물러 있습니다). "통일"이 다운그레이드가 되는 순간이었습니다. 통일 대상에서 제외하고, Boot 4 세대로 올라갈 때 전 레포를 내장 방식으로 옮기는 것으로 방향을 정리했습니다.

 

함정 1: 표준을 복사했더니 운영이 DEBUG가 될 뻔했다

가장 큰 함정이었습니다. 표준 원본의 logback-spring.xml 은 root 요소가 이렇게 생겼습니다.

<root>
    <appender-ref ref="ECS_CONSOLE"/>
</root>

level 속성이 없습니다. 이 파일을 그대로 33개 설정 파일로 복사했고, 검증 단계에서 세 레포가 같은 지적으로 걸렸습니다. 커스텀 logback-spring.xml 이 잡히는 순간 Spring Boot는 자기 기본 설정(base.xml, root INFO)을 로드하지 않고, logback의 태생적 기본값은 DEBUG입니다. root에 level이 없고 logging.level.root 프로퍼티도 없으면, 운영 루트 레벨이 조용히 DEBUG로 떨어집니다.

 

 표준 원본은 왜 멀쩡했을까요. 사실 멀쩡하진 않았습니다. REST 계열 세 모듈은 짝이 되는 application-prod.yml 에 logging.level.root: INFO 를 갖고 있었지만, grpc와 consumer 모듈은 그 yml조차 없었습니다. 즉 그 템플릿은 단독으로 성립하는 표준이 아니라 yml과 세트로만 성립하는 표준이었고, 세트의 반쪽만 복사한 것입니다. 대상 레포 다수가 프로파일 yml 자체를 갖고 있지 않았습니다. 33개 파일 전부 <root level="INFO"> 로 명시하는 것으로 수정했습니다. Spring의 logging.level.root 는 XML보다 우선하므로, dev에서 ${LOGGING_LEVEL:info} 로 덮는 운영 방식은 그대로 동작합니다.

 

함정 2: ${spring.profiles.active:-prod} 는 항상 "prod"다

logback의 ${...} 치환은 시스템 프로퍼티, 컨텍스트 프로퍼티, OS 환경변수만 읽습니다. Spring Environment의 프로퍼티는 못 읽습니다. 그래서 이렇게 쓰면,

<serviceEnvironment>${spring.profiles.active:-prod}</serviceEnvironment>

치환이 실패하고 항상 기본값 "prod"가 박힙니다. 개발 환경 로그가 전부 service.environment: prod 로 찍히는 버그이고, 표준 원본도 도입 초기에 이걸 밟고 springProperty 로 고친 이력이 있습니다.

<springProperty scope="context" name="activeProfile" source="spring.profiles.active" defaultValue="unknown"/>
...
<serviceEnvironment>${activeProfile}</serviceEnvironment>

이번 조사 때 보니 이미 ECS를 쓰던 레포 두 곳에도 같은 패턴이 있어 함께 교정했습니다. 잘못된 기본값의 무서운 점은 에러가 없다는 것입니다. 로그는 정상적으로 나가고, 값만 틀립니다.

 

함정 3: 한 앱의 classpath에 같은 설정 파일이 두 개

 멀티모듈 레포에서 앱 모듈 A가 라이브러리 모듈 B에 의존하는데, B에 logback-spring.xml 이 이미 있다고 합시다. A에 표준 파일을 "추가"하는 순간 classpath에 같은 이름의 파일이 두 개가 됩니다. 어느 쪽이 이기는지는 jar 로딩 순서에 좌우되고, 빌드 방식에 따라 결과가 달라져 예측할 수 없습니다. 실제로 한 레포는 fat jar가 아니라 모든 jar를 한 폴더에 풀고 -cp /app/* 로 띄우는 구조여서 이 위험이 이론이 아니라 실제 조건이었고, 배포 구조 문제까지 얹혀 이번 롤아웃에서는 제외하고 별도 작업으로 넘겼습니다.

 

원칙은 하나입니다. 앱 하나의 런타임 classpath에 logback-spring.xml 은 정확히 하나여야 합니다. 파일을 어디에 추가할지는 모듈 구조가 아니라 의존 그래프를 따라 결정해야 했습니다. 배포되는 앱 모듈이 아니라 그 앱이 의존하는 라이브러리 모듈의 파일이 실제 설정인 경우가 두 레포에서 나왔습니다.

비슷한 결로, 사고 도메인 레포는 root에 콘솔과 함께 Sentry appender가 물려 있었습니다. 표준대로 root를 통째로 갈아끼우면 에러 리포팅이 아무 경고 없이 끊깁니다. 콘솔 appender만 ECS로 교체하고 Sentry는 남기는 식으로, "표준 적용"과 "기존 동작 보존"을 파일 단위로 분리했습니다.

이 작업은 레포 17개를 전수 조사하고 11개 레포에 병렬 적용하며 레포마다 교차 검증을 거쳤고, 함정 1의 세 건은 적용 단계가 아니라 검증 단계에서 잡혔습니다. 지난 5월 레퍼런스 서버에 표준을 먼저 도입하고 springProperty 버그까지 고쳐 둔 선행 작업이 있었기에 출발할 수 있었던 일이기도 합니다.