Log의 필요성과 주의점

Logger 중 하나인 Log4j2

들어가며

백엔드 개발자(또는 개발자를 준비하는 사람)이라면 로그는 정말 중요하다는 말을 많이 듣게 됩니다.

저 역시 초반에 귀가 닳도록 들었고, 그에 대한 중요성을 인지하고는 있었으나 몇 개의 프로젝트를 진행하다 보니 시간이 지나면서 비로소 직접 느끼기 시작했습니다.

본 글을 통해 로그가 왜 중요한지 그리고 어떤 점에서 주의를 해야 할지 경험에서 느낀 저의 생각을 전달하려고 합니다.

 

Log는 왜 필요하고 중요할까?

애초에 왜 로깅이 필요한지에 대해서 얘기해보려고 합니다.

일단 잠시 모든 것을 제쳐두고, 소제목처럼 원초적인 질문에 대해서 저의 한 문장의 대답은 이렇습니다.

어떠한 시스템 즉 프로그램은 항상 예기치 못한 오류와 버그들로 가득 차 있고, 복잡한 코드 사이에서 버그가 발생했던 정확한 시간과 위치를 알아내고 기록하기 위함이다.

위와 같은 목적을 달성하기 위해서 Java를 사용하는 개발자는 코딩 테스트 때부터 사용하여 꽤 익숙한 System.out.println(); 를 사용하면 된다고 생각할 수 있습니다.

 

하지만 이를 실제 운영 및 개발환경에서 사용하기에는 다소 무리가 있는 다음과 같은 단점들이 알려져 있습니다.

• 내용이 저장되지 않고 휘발된다
• 성능 저하의 원인이 된다
• 로그 레벨 구분이 불가능하다

내용이 저장되지 않고 휘발된다

System.out.println(); 은 콘솔에 내용을 단순하게 출력하기만을 위한 용도입니다.

따라서 서버 내에서 실행되는 프로그램이 종료나 재시작을 하게 된다면 실행했던 기간에 쓰였던 모든 내용이 사라지게 됩니다.

그렇게 되면 로깅의 목적 중에 기록이라는 부분을 만족하지 못하게 되죠.

PrintStream out = new PrintStream(new FileOutputStream("log.txt"));
System.setOut(out);
System.out.println("로그 메시지");

 

이와 같이 파일을 생성하여 기록할 수는 있겠으나, System.setOut(out); 부분을 보시면 아시겠지만 JVM 전체의 표준 출력을 바꾸게 됩니다.

그렇게 된다면 테스트 용이성 하락이 발생하거나 다른 라이브러리, 프레임워크, 심지어 JDK 내부 클래스들도 영향을 받을 수 있습니다.

또한, 저대로라면 파일도 하나뿐으로 거대해질 것이기 때문에 수동으로 파일 관리를 직접 구현도 해야 합니다.

 

성능 저하의 원인이 된다

가장 중요한 것 중 하나인 성능과도 깊은 연관이 있습니다.

이를 제대로 이해하기 위해서 JDK의 일부 코드이며 java.lang 패키지 내에 있는 System 클래스의 내용부터 보았습니다.

System 클래스는 private 생성자를 가지고 있어 따로 인스턴스를 생성하지 못하고, out과 같이 여러 static 변수 및 유틸 메서드를 제공하는 역할을 합니다.

위 코드를 보았을 때는 null로 초기화되지만 주석들에 의하면 registerNatives();라는 native 메서드를 통해 JVM이 초기화될 때 설정이 완료됩니다.

 

out의 정체는 PrintStream이라는 클래스였습니다. 이번에는 PrintStream 클래스의 내용을 보겠습니다. 그중에서도 println()을 살펴봅시다.

이 메서드의 parameter는 int, long, char, String 등으로 다양하게 overloading 되어 있습니다.

그중에서도 많이 사용하는 println(String x)는 다음과 같습니다.

 

println()은 print()와 newLine()을 함께 실행하는 것을 알 수 있습니다.

이때 눈에 띄게 보이는 것은 lock과 synchronized(this)입니다.

즉 내부적으로 동기화 처리를 하고 있는 것이고, 해당 메서드를 호출하는 critical section들을 단일 스레드로 처리하도록 합니다.

Spring Boot가 실행하는 WAS(Tomcat)가 멀티스레드 기반의 서블릿 컨테이너에서 구동되는 상황에서 이러한 동기화 처리는 병목현상을 유도합니다.

실제 서비스에서는 매초마다 수많은 요청이 오는데, 병목 현상으로 인해 순서대로 완료되어야 하고 요청 완료가 전체적으로 늦어집니다.

조금 더 깊이 들어가 보면 flush와 buffer 원리도 따라가게 되는데 이에 대해서는 여기보다는 추후에 별도로 글을 작성해 보겠습니다.

 

로그 레벨 구분이 불가능하다

로그를 상황 구분 없이 모두 남기는 것은 메모리 공간이나, 성능적인 면에서도 비효율적입니다.

보통은 개발 환경과 프로덕션 환경의 차이에서 예시를 듭니다.

로컬에서 코드를 돌리거나 QA 환경에서는 좀 더 세세한 로그들을 남기면서 분석하는 반면, 실제 프로덕션에서는 오류나 사용자의 접속 기록 등만 로그를 남깁니다.

println();은 환경에 구분 없이 무조건 실행되기 때문에 개발자가 직접 구현해야만 합니다. 그렇게 되면 코드가 너무 복잡해지고 생산성이 급격하게 하락할 것입니다.

이를 해결하기 위해 보통 Logger에는 TRACE, DEBUG, INFO, WARN, ERROR, FATAL와 같은 레벨을 가지고 있습니다.

 

주의점

Log4j2, Logback, java util logging 등 다양한 로거가 존재하고 이들 중 하나를 선택하였다고 가정하겠습니다.

이제 println() 메서드를 사용하지 않으니 그냥 마음 편하게 개발을 이어가면 될지도 모르겠다고 생각할 수도 있습니다.

Configuration을 잘 구성해서 코드 사이에 적절하게 logger를 넣는 것으로 웬만해서는 문제가 없겠지만, 예외 처리 부분에서 의도치 않는 작동이 일어날 수 있습니다.

이 부분에 대해서는 별도로 예외 처리에 관한 이야기로 풀지 고민했지만, 로그와도 어느정도 연관이 있어 저의 경험과 함께 여기서 이야기를 짧게 하려고 합니다.

 

저는 Exception이 발생할 시 RestControllerAdvice에서 인자로 받은 에러 스택을 출력하도록 하여 정확히 어디서 문제가 일어났는지 분석할 수 있게 설정한 경험이 있습니다.

그런데 인증/인가 filter 예외에서는 출력되지 않아 예외가 발생한 위치를 찾는데에 어려움을 겪었던 적이 있습니다.

 

원인으로는 RestControllerAdvice의 적용 범위가 filter 뒤에 위치한 Dispatch Servlet 내에서 발생한 예외 때문이었고 에러 스택이 logger로 전달되지 못한 것이었습니다.

따라서 filter에서는 직접 throw 전에 logger로 출력하도록 변경해서 해결했습니다.

 

이외에도 로직의 특성으로 인해 try catch에서 에러 발생 시 아무 조치없이 넘어가도록 하는 코드가 있었으나 불필요한 log.error() 작성으로 인한 혼란, 예외 되던지기에서 생략된 이전 에러 스택 등이 있었습니다.

 

로그를 출력하도록 코드를 작성하는 것은 정말 좋으나, 의도했던 상황에서 정말로 적절한 로그가 출력되고 저장되는지 꼭 확인하고 (테스트 코드 등을 이용하여) 신경 쓰는 것이 좋을 것 같습니다.