AOP 로깅을 통한 효율적인 로깅 로직 구현하기
이번에도 라인업지 서비스를 진행하면서 적용했던 기술적 도전을 간단하게나마 풀어보려 한다.
매번 라인업지 서비스를 가져와서 '또 라인업지야?'라고 느끼실 수 있을 것 같다고 생각한다.
하지만 그만큼 해당 프로젝트가 필자로 하여금 수많은 기술적 도전을 통해 한층 더 성장하게 만들어 주었기에, 다양한 문제를 해결하며 얻은 교훈과 성장의 흔적들을 여러 글에 걸쳐 정리해보려고 하는 것이니 이해해 주시면 정말 감사하겠다ㅎㅎ 🥹
그럼 각설하고, AOP 로깅을 적용하게 된 계기를 우선 말씀드리면서 시작하겠다.
AOP 로깅의 적용 계기와 기존 로깅 로직의 한계점
우리가 보통 로깅을 비즈니스 로직에 적용한다고 하면, @slf4j 어노테이션을 통해 비즈니스 로직에 다음과 같은 코드를 끼워 넣어 다음과 같이 구현한다.
해당 코드가 잘못된 코드는 아니다! 다만 해당 방식으로 로그를 계속 구현하는 것은 다음과 같은 문제들을 수반하기 마련이다.
- 비즈니스 로직이 늘어날 때마다 불필요한 반복적인 로깅 로직을 작성해야 함.
- 로그 내용을 수정하려면, 모든 로깅 로직을 찾아 수정해야 함.
- 로깅 로직이 중간에 자리를 차지해 비즈니스 로직의 가독성이 떨어짐.
단순히 비즈니스 로직이 한두 개 정도라면 위의 예시와 같이 작성해도 무방하다!
하지만 본인의 경우, 수 십 개의 비즈니스 로직과 컨트롤러를 통해 들어오는 요청에도 로깅을 구현해주고 싶었고, 무엇보다 비즈니스 로직의 핵심 관심사가 부가적인 로직에 의해 오염되는 것을 방지하고 싶었다.
해당 요구사항을 종합적으로 따져봤을 때, AOP를 적용한 로깅을 적용할 수밖에 없었다.
AOP
AOP, Aspect Oriented Programming은 관점 지향 프로그래밍이라고 불린다.
개념은 단순하다. 관점에 따른 관심사를 분리하는 것이다. 다시 말해, 특정 로직의 핵심 관심사로부터 횡단(부가) 관심사를 분리하는 것이다.
우리가 흔히 코드를 작성하면, 여러 비즈니스 로직 또는 클래스에 같은 내용이지만 반복해서 사용하는 로직들을 발견할 수 있다. 이를 우리는 흩어진 관심사라 부른다.
흩어진 관심사를 우리는 관점에 따라 분리하여, 분리된 관심사는 각각 모듈화를 통해 구현되며 이를 통해 다음과 같은 장점을 지니게 된다.
- 비즈니스 로직의 가독성 증가
- 모듈성 증가로 인한 유지보수성 증가
- 단일 책임 원칙에 따른 사이드 이펙트 감소
주요 개념
- JointPoint : 특정 메서드에서 횡단 관심사가 수행될 시점을 의미
- PointCut : 횡단 관심사가 수행될 대상을 의미
- Advice : 횡단 관심사를 구현한 실제 구현체
- Aspect(JointPoint + Advice) : 횡단 관심사와 해당 관심사가 수행될 시점을 결합하여 모듈화 한 객체
AOP 로깅 구현
의존성 추가
implementation 'org.springframework.boot:spring-boot-starter-aop'
우선 build.gradle에 AOP를 사용하기 위해 의존성을 추가해 준다.
어드바이스 주요 개념
- @Pointcut : 로직이 수행될 대상을 지정, 주로 로그를 다르게 표현해주고 싶은 대상을 별도로 지정
- @Around : 메서드 호출 전/후에 수행
- @Before : 메서드 호출 전에 수행
- @AfterReturning: 메서드 호출 이후 해당 메서드가 정상적으로 종료되었을 때 동작
- @AfterThrowing: 메서드 호출 이후 해당 메서드에서 예외가 발생했을 때 동작
@PointCut
@PointCut 어노테이션을 통해 우리는 로깅의 대상을 메서드 형태로 지정할 수 있다.
이때 Spring에서 제공해 주는 정규표현식을 통해 원하는 대상을 직접 지정해 줄 수 있는데, execution 앞에 '!'를 지정해 주어 특정 대상은 지정 범위에서 제외할 수도 있다. 본인은 우선 비즈니스 로직과 컨트롤러 단에서 로그로 출력하고 싶은 내용이 달라 별도의 메서드로 분리해 주었다. 그리고 로드 밸런서에 활용되는 상태 확인 API와 같은 로깅에 있어 불필요한 대상은 추가적으로 제외해 주었다.
@Around
@Around 어노테이션을 통해 메서드 호출 전/후에 처리할 수 있는 로직을 자유롭게 정의할 수 있다. 메서드 호출 이전과 이후의 동작을 모두 제어할 수 있기에, 가장 강력한 어드바이스로 간주된다.
jointPoint.proceed()를 기점으로 메서드의 실행 전과 후에 실행할 로직을 정의할 수 있다. 따라서 시작하기 전에 현재 시간을 측정하여 변수에 할당하고, 메서드가 끝난 이후 현재 시간과 start 변수를 비교하여 목표 메서드의 경과 시간을 측정할 수 있도록 하였다. 또한 실행했던 클래스의 이름과 메서드명을 getSignature()를 통해 가져와 최종적으로 로그에 출력할 수 있도록 하였다!
이를 통해 모든 클래스의 모든 메서드의 소요 시간을 보다 편리하게 파악할 수 있게 하였다.
@Before
@Before 어노테이션을 통해 특정 메서드가 실행 전에 수행할 작업을 지정해 줄 수 있다. 본인은 컨트롤러를 통해 들어오는 요청을 다음과 같이 로깅하였다.
- HTTP 요청 방식
- 요청 URI
- 컨트롤러 클래스명
- 메서드명
- 매개변수
컨트롤러 클래스명과 메서드는 getSignature()을 통해 변수에 할당해 주었고, HTTP 요청 방식과 요청 URI는 HttpServletRequest 객체에서 추출하였다.
그리고 매개변수는 HttpServletRequest 객체를 통해 인자값들을 추출하여 JSON 객체로 담아서 반환하는 getParams() 메서드를 구현하여 담아주었다!
@AfterReturning
@AfterReturning 어노테이션을 통해 지정 메서드의 반환 값을 가져올 수 있다. 하지만 API에 따라 따라서 응답 객체가 방대할 경우, 오히려 가독성이 떨어져 효율적인 로깅을 저해할 수 있다는 단점이 존재한다. 따라서 본인은 특정 API가 정상적으로 처리되었을 때, 해당 API의 메서드명과 응답 상태 코드만 표기하도록 구현하였다.
@AfterThrowing
@AfterThrowing 어노테이션을 통해 지정 메서드에서 예외가 발생했을 경우, 해당 예외에 대한 정보를 가져올 수 있다. 위에서 언급했듯이 과도한 정보량은 오히려 가독성을 해치기에, 예외를 설명해 주는 Message 값과 해당 예외가 발생한 메서드명을 가져와 로그로 출력하였다.
결과
해당 스크린샷은 최초로 AOP 로깅을 구현했을 때 캡처한 것이다. 실제 운영 때에는 로그의 가독성을 고려해 필수적인 정보만 담아 로깅하도록 수정하였다.
놀랍게도 이틀 동안 트래픽이 약 170만 건을 돌파해.. 생각보다 로그를 일일이 지켜보는 것은 무척 어려웠다. 다행히 이를 대비해 Pinpoint를 구축해 보다 안정적인 모니터링을 진행할 수 있었다. 비록 구현한 AOP 로깅을 통해 효율적인 모니터링을 진행하지는 못했지만, 나름 의미 있는 경험이었다고 생각한다.
AOP 로깅을 처음 도입하며 얻은 가장 큰 교훈은, 모든 데이터를 기록하는 것보다 필요한 정보를 선별적으로 로깅하는 것이 중요하다는 점이었다. 운영 환경에서는 로그의 양이 (매우)폭발적으로 증가하기 때문에, 불필요한 데이터를 남기는 것은 분석에 오히려 방해가 될 수 있다.
느낀 점
비록 AOP 로깅 자체로는 모든 모니터링 요구사항을 충족시키지 못했지만, 이는 로깅의 중요성과 한계를 체감할 수 있는 기회가 되었다. 더불어, Pinpoint 같은 모니터링 툴을 도입하여 보다 체계적이고 시각적인 모니터링 환경을 구축할 수 있었던 점이 뜻밖의 수확이었다. 추후 Pinpoint 구축 회고도 작성할 예정이다 ㅎㅎ.
결론적으로, 로깅은 단순 기록이 아닌 운영과 최적화를 위한 도구로서 구현되어야 한다는 점을 깨닫게 되었다. 앞으로는 트래픽이 급증하는 환경에서도 효과적으로 동작할 수 있는 최적화된 로깅 설계와 APM 통합 전략을 고민할 것 같다.