logback-spring.xml<configuration>
<property name="LOG_PATTERN"
value="%d{HH:mm:ss.SSS} %-5level [%thread] %X{traceId} %logger{36} - %msg%n"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder><pattern>${LOG_PATTERN}</pattern></encoder>
</appender>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>/var/log/app/app.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>/var/log/app/app.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
<maxFileSize>50MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
<encoder><pattern>${LOG_PATTERN}</pattern></encoder>
</appender>
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>1024</queueSize>
<discardingThreshold>0</discardingThreshold>
<neverBlock>true</neverBlock>
<appender-ref ref="FILE"/>
</appender>
<springProfile name="prod">
<root level="INFO">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="ASYNC"/>
</root>
</springProfile>
<springProfile name="!prod">
<root level="DEBUG">
<appender-ref ref="CONSOLE"/>
</root>
</springProfile>
</configuration>%X{traceId} 가 MDC 값을 패턴에 꽂아 넣고, discardingThreshold=0 은 큐가 차도 로그를 버리지 않되 neverBlock 으로 요청 스레드를 막지 않습니다. springProfile 로 운영은 INFO, 나머지 환경은 DEBUG 를 기본값으로 나눕니다.
@Async 전파@Component
public class TraceIdFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res,
FilterChain chain) throws ServletException, IOException {
String traceId = UUID.randomUUID().toString().substring(0, 8);
MDC.put("traceId", traceId);
res.setHeader("X-Trace-Id", traceId);
try {
chain.doFilter(req, res);
} finally {
MDC.clear(); // 스레드 풀 재사용 대비, 반드시 finally
}
}
}
@Configuration
public class AsyncConfig implements AsyncConfigurer {
@Override
public Executor getAsyncExecutor() {
ThreadPoolTaskExecutor exec = new ThreadPoolTaskExecutor();
exec.setTaskDecorator(runnable -> {
Map<String, String> ctx = MDC.getCopyOfContextMap();
return () -> {
if (ctx != null) MDC.setContextMap(ctx);
try { runnable.run(); } finally { MDC.clear(); }
};
});
exec.initialize();
return exec;
}
}OncePerRequestFilter 는 요청 하나에 한 번만 실행되어 필터 체인이 여러 번 거치는 요청도 중복 없이 traceId 를 심습니다. TaskDecorator 는 @Async 메서드가 다른 스레드로 넘어갈 때 MDC 를 복사해 데모 [3]의 Mdc.wrap 을 Spring 답게 옮긴 코드입니다.
개발 환경은 SQL 을 눈으로 보며 디버깅해야 하므로 로거를 DEBUG 로 켭니다.
# application-dev.properties
logging.level.com.company.mapper=DEBUG이 설정을 켜면 실행되는 쿼리와 바인딩 파라미터가 그대로 콘솔에 찍힙니다. 운영에서는 이 로그가 너무 많아지므로 끕니다.
느린 쿼리만 06 레슨의 MyBatis Interceptor 로 잡아 WARN 을 남깁니다.
@Intercepts(@Signature(type = Executor.class, method = "query",
args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}))
public class SlowQueryInterceptor implements Interceptor {
private static final Logger log = LoggerFactory.getLogger(SlowQueryInterceptor.class);
private static final long THRESHOLD_MS = 1000;
@Override
public Object intercept(Invocation inv) throws Throwable {
long start = System.currentTimeMillis();
try {
return inv.proceed();
} finally {
long elapsed = System.currentTimeMillis() - start;
if (elapsed > THRESHOLD_MS) {
MappedStatement ms = (MappedStatement) inv.getArgs()[0];
log.warn("slow query {}ms {}", elapsed, ms.getId());
}
}
}
}운영에서는 항상 켜져 있어도 부담이 없고, 느린 쿼리만 눈에 띄게 걸러 줍니다.
폐쇄망에서도 셸 기본 도구만으로 로그를 분석할 수 있습니다.
# traceId 로 한 요청의 모든 줄 추출
grep "79d2a28e" app.log
# 특정 시간 구간(10:52:17 ~ 10:52:18)만 추출
awk '$1 >= "10:52:17.000" && $1 <= "10:52:18.999"' app.log
# ERROR 로 남은 메시지를 종류별로 집계 (많이 난 것부터)
grep "SEVERE\|ERROR" app.log | cut -d'-' -f2- | sort | uniq -c | sort -rn | head
# JSON 로그는 jq 로 필드를 골라 본다
cat app.json.log | jq -r 'select(.level=="ERROR") | .msg'
# 여러 인스턴스의 롤링 파일을 시간 순으로 합쳐서 본다
sort -m app.0.log app.1.log app.2.log | less수집기가 없는 서버에서도 이 다섯 줄이면 "누가, 언제, 무슨 오류가 몇 번" 났는지 대부분 답이 나옵니다. jq 가 없는 순수 폐쇄망 서버라면 JSON 도 결국 한 줄 텍스트이므로 grep·awk 로도 필드를 잘라낼 수 있습니다.
이 명령들을 셸 스크립트 한 파일로 모아 두면, 장애가 났을 때 매번 새로 생각해내지 않고 바로 실행할 수 있습니다. 수집기가 생기더라도 로컬에서 급하게 확인할 때는 여전히 이 방식이 가장 빠릅니다.