로그 잘 남기면 디버깅이 수월해짐

개발용 서버에선 프로덕션 서버로 배포되기 전 QA작업이 이뤄지고, 프론트엔드와의 협업시 사용되기 때문에 로컬에서 발견하지 못한 버그를 발견하게 되는 케이스가 꽤 잦았다. 하지만, 부실한 로그를 남기고 있었다면, 개발 서버 자체에서 버그의 발생 경로를 추측하는 데에 어려움이 있었다.

그래서 프로젝트의 로깅 정책에 debug레벨로 개발서버와 로컬 환경에서 모든 작업에 대한 트레이싱 정보를 남기는 정책을 추가했다.

왜 개발용 서버에서만 트레이싱 로그를 남겨야 하는가

로컬 환경에서 버그를 발견했다면, 대부분의 개발자는 IDE의 디버깅 모드로 디버깅을 시도할 것이다.

하지만, 로컬 환경이 아니라 서버에 올라간 프로그램의 경우 IDE의 기능을 이용할 수 없기에 어플리케이션이 남겨놓은 로그에 디버깅을 의존하게 된다.

실제 프로덕션 환경에서 디버깅을 위한 로그를 남기는 것은 적절하지 않을 수 있다.

디버깅용으로 남기는 로그들이 보안상 치명적일 수도 있고, 로그를 남긴다는 건 어쨌든 디스크에 IO작업이 있는 것이기 때문에, 너무 많은 로그를 남기는 건 프로덕션 환경에서 불필요한 성능 저하를 불러일으킬 수 있다.

따라서 이번 포스팅에서 다룰 디버깅용 로그는 프로덕션 환경으로 가기 전, 개발용 서버에 배포되었을 때만 남기는 로그로 프로젝트 로깅 정책을 정했다.

---

AOP를 사용해 로깅한다.

모든 작업에 대해 로그를 남긴다. 모든 메서드 호출마다 이런 코드를 직접 끼워 넣는건 말이 안된다. 개발을 할 때마다 로깅을 신경써야 하기 때문에 개발자의 관심사도 집중되지 못할 것이며, 코드에서도 로깅을 위한 코드와 메서드의 핵심 로직을 위한 코드가 공존할 것이다.

이런 문제를 해소하기 위해 스프링 AOP를 사용해서 로깅에 대한 관심사를 완전히 분리할 것이다.

어드바이저는 이렇게 작성했다.

@Around("allComponents() && !noLogging()")
public Object doLogTrace(final ProceedingJoinPoint joinPoint) throws Throwable {
    final String message = joinPoint.getSignature().toShortString();
    final Object[] args = joinPoint.getArgs();
    try {
        loggingTracer.begin(message, args);
        final Object result = joinPoint.proceed();
        loggingTracer.end(message);
        return result;
    } catch (final Exception e) {
        loggingTracer.exception(message, e);
        throw e;
    }
}

---

작업마다 ID를 부여한다.

웹 어플리케이션 서버의 특성상 여러 요청이 동시에 처리되는 멀티 스레드 환경이다. 그래서 로그의 순서가 뒤죽박죽일 수 있으며, 어떤 로그가 어떤 작업에서 찍혔는지 알아보기 어려울 수 있다. 작업에 ID를 부여하면, 해당 ID로 필터링해서 로그를 볼 수 있기 때문에 각 작업끼리의 로그 구분이 쉬워진다.

스레드 ID를 활용할 수 있지 않나?

톰캣에서 작업에 대한 스레드는 톰캣이 미리 생성해둔 스레드 풀에서 꺼내와서 이뤄진 후에 스레드를 풀에 반납한다. 즉 스레드는 재사용 되는 것이다. 따라서 스레드 ID로 필터링 한다면 로그의 순서가 꼬이진 않겠지만, 해당 스레드ID는 진짜 고유한 작업에 대한 ID가 아니기 때문에 여러 작업을 처리할 것이고, 작업끼리 명확히 구분짓기는 어려울 수 있다.

작업 ID를 관리하기 위해서 다음과 같은 클래스를 정의했다.

LoggingStatus

public class LoggingStatus {

    private final String taskId;
    private final long startTimeMillis;
    private int depthLevel = 0;

    public LoggingStatus(final String taskId, final long startTimeMillis) {
        this.taskId = taskId;
        this.startTimeMillis = startTimeMillis;
    }

    public void enterDepth() {
        depthLevel++;
    }

    public void comeOutDepth() {
        depthLevel--;
    }

    public boolean isEndDepth() {
        return depthLevel == 0;
    }

    // getters...
}

LoggingStatusManager

@Component
public class LoggingStatusManager {

    private final ThreadLocal<LoggingStatus> statusContainer = new ThreadLocal<>();

    public void syncStatus() {
        final LoggingStatus status = statusContainer.get();
        if (status != null) {
            status.enterDepth();
            return;
        }
        final LoggingStatus firstLoggingStatus = createLoggingStatus();
        statusContainer.set(firstLoggingStatus);
    }

    private LoggingStatus createLoggingStatus() {
        final String traceId = SecureRandomStringUtils.createRandomAlphanumericSecure(10);
        final long startTimeMillis = System.currentTimeMillis();
        return new LoggingStatus(traceId, startTimeMillis);
    }

		public void release() {
        final LoggingStatus status = getExistLoggingStatus();
        if (status.isEndDepth()) {
            statusContainer.remove();
            return;
        }
        status.comeOutDepth();
    }

    private LoggingStatus getExistLoggingStatus() {
        final LoggingStatus status = statusContainer.get();
        if (status == null) {
            throw new IllegalStateException();
        }
        return status;
    }

    // methods...
}

스레드마다 로깅을 위한 작업 정보를 갖는 LoggingStatus라는 클래스를 정의했고, 이걸 LoggingStatusManager클래스에서 ThreadLocal로 관리한다.

작업이 모두 종료됐을 시에 release를 호출해서 ThreadLocal 에서 비워주도록 했다.

위 구조는 스프링에서 트랜잭션 동기화 매니저가 커넥션을 다루는 부분을 보고 영감을 받아서 작성했다.

---

메서드 실행 마다 트레이스를 남긴다.

이건 코드를 먼저 보겠다.

@Component
@Slf4j
@RequiredArgsConstructor
public class LoggingTracer {

    private static final String TRACE_DEPTH_SPACE = "--";
    private final LoggingStatusManager loggingStatusManager;

    public void begin(final String message, final Object[] args) {
        loggingStatusManager.syncStatus();
        if (log.isDebugEnabled()) {
            log.debug(
                    "[{}] {}--> {} args={}",
                    loggingStatusManager.getTaskId(),
                    getDepthSpace(loggingStatusManager.getDepthLevel()),
                    message,
                    args
            );
        }
    }

    public void end(final String message) {
        final long stopTimeMillis = System.currentTimeMillis();
        final long resultTimeMillis = stopTimeMillis - loggingStatusManager.getStartTimeMillis();

        if (log.isDebugEnabled()) {
            log.debug(
                    "[{}] {}<-- {} time={}ms",
                    loggingStatusManager.getTaskId(),
                    getDepthSpace(loggingStatusManager.getDepthLevel()),
                    message,
                    resultTimeMillis
            );
        }

        loggingStatusManager.release();
    }

    public void exception(final String message, final Exception e) {
        final long stopTimeMillis = System.currentTimeMillis();
        final long resultTimeMillis = stopTimeMillis - loggingStatusManager.getStartTimeMillis();

        if (log.isDebugEnabled()) {
            log.debug(
                    "[{}] <X-{} {} time={}ms ex={}",
                    loggingStatusManager.getTaskId(),
                    getDepthSpace(loggingStatusManager.getDepthLevel()),
                    message,
                    resultTimeMillis,
                    e.toString()
            );
        }
        loggingStatusManager.release();
    }

    private String getDepthSpace(final int depthLevel) {
        return TRACE_DEPTH_SPACE.repeat(depthLevel);
    }
}

메서드 시작시에 작업ID, 메서드 정보, 그 메서드의 아규먼트 정보를 로깅한다.

그리고 메서드 시작시 로깅 뎁스를 1씩 증가시켜 로그가 남을 때 몇 뎁스 들어가서 이 메서드를 실행했는지도 남긴다.

메서드가 끝날땐 마찬가지로 작업 ID와 메서드 정보를 남기고, 추가로 그 메서드가 종료되는데 걸린 시간을 로깅한다. 만약 해당 메서드에서 성능 문제가 발생했다면 이 로그를 통해 유추해볼 수 있다.

메서드를 실행하다 예외가 발생했다면, 여기에 추가로 예외 정보도 같이 로깅한다.

 

해당 코드를 반영시켜 실행되는 로그의 예시를 보겠다.

이제 개발 서버에서도 꽤 괜찮은 수준의 디버깅이 가능할 것이다.