Spring 제대로 활용해보는 로깅 개발 여정

JungYun

Published in

SSG TECH BLOG

22 min readJan 17, 2023

시작 전 당부사항: 스프링을 이미 많이, 깊이 알고 계신 분들은 새롭게 얻어가시는 건 없을 수 있습니다. 제가 빠졌던 함정들을 파두었으니, 찾아내는 재미로 읽어주시면 감사하겠습니다.

또한 이해를 돕기 위해 삽입한 코드는 실제 코드를 아주 간소화하였으며, 의사코드 식으로 작성하기도 했습니다.

안녕하세요. SSG.COM 제휴서비스팀 오정윤입니다.

저는 외부 제휴사들에서 결제완료된 SSG 상품 주문 데이터를 가져와서 SSG의 주문으로 만드는 연동업무를 하고 있습니다.

연동 과정에서 여러 API를 호출하기 때문에 모니터링과 문제가 생겼을 때의 디버깅을 위해 API 요청, 응답 전문을 DB에 저장하고 있습니다.

API 를 호출할 때마다 로깅을 해야하니 AOP로 구현하고 있었는데요.

이때 각 API 호출 기능을 하는 메소드들에 로깅에 필요한 현재 처리중인 주문 정보 — 주문번호, 어떤 제휴사인지 — 를 넘겨주기 위해 기존에는 파라미터를 넘기는 방식을 사용했었습니다.

혹시 이 경우에 파라미터를 넘기는 것 대신에 어떤 방법이 좋을지 바로 떠오르시나요?? 주문 생성 요청 들어온 주문 정보를 로깅하는 AOP에서 참조할 수 있으면 됩니다.

제가 사용하기로 한 것은 바로 request scope 입니다.

Request Scope Bean 적용한 로깅 도입

다음은 인프런에 있는 유명한 스프링 강의인 김영한님의 스프링 핵심원리 9장 빈 스코프 에서 발췌한 내용입니다.

request scope: HTTP 요청 하나가 들어오고 나갈 때 까지 유지되는 스코프, 각각의 HTTP 요청마다 별도의 빈 인스턴스가 생성되고, 관리된다. (중략) request scope를 사용하지 않고 파라미터로 이 모든 정보를 서비스 계층에 넘긴다면, 파라미터가 많아서 지저분해진다. 더 문제는 requestURL 같은 웹과 관련된 정보가 웹과 관련없는 서비스 계층까지 넘어가게 된다. 웹과 관련된 부분은 컨트롤러까지만 사용해야 한다. 서비스 계층은 웹 기술에 종속되지 않고, 가급적 순수하게 유지하는 것이 유지보수 관점에서 좋다.
request scope의 MyLogger 덕분에 이런 부분을 파라미터로 넘기지 않고, MyLogger의 멤버변수에 저장해서 코드와 계층을 깔끔하게 유지할 수 있다.

한 주문이 한 HTTP 요청으로 들어오기 때문에 저희 상황에 딱 맞는 해결책이었습니다.

Bean은 아래와 같습니다.

@Component
@Scope(value="request") // request 스코프로 지정. 이제 이 빈은 HTTP 요청 당 하나씩 생성되고, HTTP 요청이 끝나는 시점에 소멸.
public class TestRequestBean {

    private String allnOrdNo;
    private String mallNm;
    private AllnDiv allnDiv;

    public enum AllnDiv {
        ORDER, CLAIM;
    }
}

요청이 들어오면 interceptor에서 주문 정보를 bean에 세팅해줍니다.

public class TestInterceptor implements HandlerInterceptor {
  
  private final ObjectProvider<TestRequestBean> testBeanProvider;
  
  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    ...
    TestRequestBean testRequestBean = testBeanProvider.getObject();
    testRequestBean.setMallNm("MALL_NAME");
    testRequestBean.setAllnDiv(RequsetMarketDataBean.AllnDiv.ORDER);
    ...
    return true;
  }
}

request scope bean은 실제 고객의 요청이 와야 생성되기 때문에 private final TestRequestBean testRequestBean;이런식으로 스프링 빈 로딩 시점에 생성해서 주입하려 하면 BeanCreationException 납니다.

Error creating bean with name 'testRequestBean': Scope 'request' is not active for the current thread; consider defining a scoped proxy for this bean if you intend to refer to it from a singleton; nested exception is java.lang.IllegalStateException: No thread-bound request found: Are you referring to request attributes outside of an actual web request, or processing a request outside of the originally receiving thread? If you are actually operating within a web request and still receive this message, your code is probably running outside of DispatcherServlet: In this case, use RequestContextListener or RequestContextFilter to expose the current request.

스프링핵심원리(기본편) 강의에서는 두가지 방법을 알려주는데요. 그 중에 ObjectProvider를 이용하여 TestRequestBean 생성을 지연시켰습니다. provider.getObject() 를 호출하는 시점에는 HTTP 요청이 진행중이므로 request scope 빈의 생성이 정상 처리됩니다.

또한 interceptor에서 getObject() 해서 얻은 bean이나, 나중에 AOP에서 getObject() 해서 얻는 bean이나 같은 HTTP 요청이면 같은 객체입니다.

그리고 어노테이션 기반 AOP를 걸어놓습니다.

@Aspect
@RequiredArgsConstructor
public class TestLoggingAspect {
  
  private final ObjectProvider<TestRequestBean> testBeanProvider;
  
  @Around("@annotation(com.test.annotation.TestLog) || @within(com.test.annotation.TestLog)")
  public Object processCustomAnnotation(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
    TestRequestBean testRequestBean = testBeanProvider.getObject();
        
    save(divId, testRequestBean.getAllnOrdNo(), ... );
    ...
  }
 
  void save(String divId, String almktOrdNo, ...) {
    ... 객체 생성 ...
    repository.save(객체);
  }
}

참고) 또 다른 방법으로는 프록시를 사용하는 방법이 있는데요.

@Component
@Scope(value="request", proxyMode = ScopedProxyMode.TARGET_CLASS)
public class TestRequestBean {
}

proxyMode 를 추가해두면 TestRequestBean의 가짜 프록시 클래스를 만들어두고 HTTP Request와 상관없이 가짜 프록시 클래스를 다른 빈에 미리 주입해 둘 수 있습니다. 이 방법은 Provider에 비해서 클라이언트의 코드는 전혀 고치지 않는다는 아주 큰 장점이 있습니다. (클라이언트에서는 그냥 private final TestRequestBean testRequestBean; 쓰면 프록시 객체가 주입되고 사용할 때는 실제 request scope 빈 메소드에게 처리 위임합니다.)

어 왜 이거 로깅이 조금 빠져있지

아래와 같이 호출하는 메소드들에 annotation을 달아서 로깅 AOP가 적용되도록 했습니다.

전반적으로는 대체로 잘 되는 것처럼 보였습니다.

@Component
@RequiredArgsConstructor
public class TestSender {

  private final ApiService apiService;

  @TestLog
  public String apiCallMethodA(String reqStr) {
      return apiService.post(path, reqStr);
  }

  @TestLog
  public String apiCallMethodB(String reqStr) {
      return apiService.post(path, reqStr);
  }

  public List<ResultDto> getResultDto(String reqStr) {
      return processParsing(apiCallMethodD(reqStr));
  }

  @TestLog
  private String apiCallMethodD(String reqStr) {
      return apiService.post(path, reqStr);
  }
}

외부에서 apiCallMethodA(), apiCallMethodB(), getResultDto() 를 호출했을 때 로깅이 어떻게 될지 예상이 되시나요??

제가 바랬던 건 apiCallMethodA(), apiCallMethodB() , 그리고 getResultDto()가 호출됐으니 apiCallMethodD()까지 로깅이 되는 것이었습니다.

하지만 실제로는 이중 일부는 되고 일부는 되지 않았는데요.

바로 apiCallMethodD() 는 로깅이 되지 않습니다.

AOP 를 학습할 때 보통 같이 배우는 AOP 주의사항 — 프록시 내부 호출 문제입니다. (기본 상식이라고 표현한 블로그도 있더라구요🥲)

Spring AOP는 프록시 기반으로 동작하는데요, 외부에서 apiCallMethodD()를 호출하면 AOP에서 정의한 동작들이 적용된 프록시 객체의 apiCallMethodD()가 호출되지만, getResultDto() 가 내부호출하는 apiCallMethodD()는 프록시의 메소드가 아니고 그냥 TestSender에 정의된 메소드 코드만 동작하게 됩니다.

출처: 인프런 김영한님 스프링핵심원리 — 고급편 13장 스프링 AOP — 실무 주의사항

(코틀린의 AOP는 proxy 기반이 아니어서 내부 함수 호출을 하더라도 적용이 된다고 합니다 https://www.podo-dev.com/blogs/278?tag=AOP)

여러 대안들이 있지만 가장 나은 대안은 내부호출이 발생하지 않도록 구조를 변경하는 것이라고 합니다. getResultDto()의 api 응답 결과 처리 하는 부분을 다른 클래스로 옮기는 것으로 해결하였습니다.

아 그리고 저 코드에서는 apiCallMethodD 가 private 인데요. AOP는 public 메서드에만 걸리므로 public으로 변경해주었습니다. (Spring AOP는 CGLIB을 사용해서 동적 프록시 생성하는데요. CGLIB은 상속을 통해 프록시를 생성하고, private 메서드는 상속이 불가능하기 때문입니다.)

롤백..

TestLoggingAspect 코드를 다시 봐주시면 제가 save() 를 하고 있습니다.

막간으로 아주 쉬운 퀴즈를 내보면 저기에 @Transactional을 붙이면 적용이 될까요??

답은 안된다 입니다. 바로 이전에 설명한 것이 여기에도 적용이 됩니다. Transactional도 AOP로 구현 = 프록시. 따라서 내부 호출되는 save()에는 프록시인 @Transactional이 적용되지 않습니다. 이 부분은 킵해두고 넘어가보겠습니다.

아래와 같이 서비스의 Transactional 선언 해놓은 메소드에서 sender의 apiCallMethodA를 호출합니다.

그리고 결과에 문제가 있으면 RuntimeException (실제로는 부가기능이 있는 RuntimeException 하위 Exception) 던집니다.

@Service
public class TestService {

    @Transactional
    void process() {
        String result = testSender.apiCallMethodA(...);
        ... result 처리 ...
        if (문제 있으면)
            throw new RuntimeException();
        
    }
}

자 여기서 제가 RuntimeException 이라고 써놓은게 힌트입니다. 바로 롤백을 언급하려고 합니다.

@Transactional은 uncheckedException 즉 RuntimeException이 발생하면 (기본전략) 롤백되어버린다는것 다들 아시죠?? 저도 여기까지는 알고 있었습니다..

다들 눈치 채셨겠지만 apiCallMethodA() 에 걸었던 로깅 AOP에서 save()가 실행되면 아직 커밋은 되지 않습니다.

저는 예외 상관없이 커밋되게 해보려고 testSender.apiCallMethodA() 내부나, AOP 에서 db save 하는 부분에 @Transactional을 걸어보기도 했는데요. 어떻게 해도 process() 에서 예외 발생하면 롤백되었습니다.

제가 몰랐던 건 제일 부모의 transaction에 합류하게 된다는 거였습니다. (그럼 결국 아는게 아니었던 것 같기도 하네요..)

결론은 제일 부모의 Transaction — 여기서는 TestService의 process() — 까지 RuntimeException이 발생하지 않아야 커밋된다는 겁니다! (중간에라도 예외 발생하면, 부모에서 예외 처리를 하더라도 전체 transaction에 rollback-only 마킹이 되어 롤백됩니다 https://techblog.woowahan.com/2606/)

물론 Java Spring에서 이렇게 쓰는건 근본적인 문제가 있습니다. Transactional이 걸려있는 로직 전체가 수행되는 동안 db connection을 갖고 있게 됩니다. 만약 이렇게 로직 중간에 api 호출을 해놨는데 서버 측에서 갑자기 지연이 생기게 된다면 몇개 없는(보통 20개) db connection들이 다 물리게 되어 connection PoolExhaustedException이 발생하게 될 겁니다.이또한 코틀린에서는 해결할 수 있는 방법이 있다고 하네요..?! https://www.podo-dev.com/blogs/285

그렇다면 저는 API 호출하고 나면 응답 처리 결과에 상관없이 그냥 커밋되었으면 좋겠는데 방법이 없는 걸까요??

교묘하게 함정이라고 만들어놔봤는데요. 기본 설정이 그렇다는 걸 안 써놨었습니다.

Transactional propagation 설정을 해주면 됩니다.

propagation 설정들 중 두가지만 적어보면

REQUIRED : (기본값) 부모 트랜잭션이 존재하면 부모 트랜잭션에 합류

REQUIRES_NEW :무조건 새로운 트랜잭션 생성.

앞서 쉬운 퀴즈 기억나시죠?? AOP에서 save() 를 호출하면 Transactional 적용이 안되기 때문에 외부에 db 저장용 서비스와 save() 를 만들고 Aspect에서는 이 메소드를 호출합니다.

@Service
@RequiredArgsConstructor
public class WriteService {

    ...

    @Transactional(propagation = Propagation.REQUIRES_NEW)
    public void save(...) {
      System.out.println("WriteService.save() 호출됨");
      repository.save(...)
    }
}

관련해서 콘솔 로그를 찍어보겠습니다.

application.yml

logging:
  level:
    org.springframework.orm: debug

propagation 기본설정 (REQUIRED) 일때

2023-01-11 15:21:42.963 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [com.ssg.api.input.order.controller.WconceptOrderController.test]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-01-11 15:21:42.963 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(382420746<open>)] for JPA transaction

2023-01-11 15:21:43.373 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(382420746<open>)] for JPA transaction
2023-01-11 15:21:43.373 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction
WriteService.save() 호출됨
2023-01-11 15:21:43.377 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(382420746<open>)] for JPA transaction
2023-01-11 15:21:43.377 DEBUG 41138 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction

propagation REQUIRES_NEW 일 때


2023-01-11 15:20:35.649 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [com.ssg.TestService.process]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-01-11 15:20:35.649 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(226336942<open>)] for JPA transaction

2023-01-11 15:20:36.047 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(226336942<open>)] for JPA transaction
2023-01-11 15:20:36.047 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Suspending current transaction, creating new transaction with name [com.ssg.WriteService.save]
2023-01-11 15:20:36.048 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1953058566<open>)] for JPA transaction
2023-01-11 15:20:36.048 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@16c69c47]
WriteService.save() 호출됨
2023-01-11 15:20:36.051 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1953058566<open>)] for JPA transaction
2023-01-11 15:20:36.051 DEBUG 41052 --- [           main] o.s.orm.jpa.JpaTransactionManager        : Participating in existing transaction

2023-01-11 15:20:36.047 DEBUG 41052 --- [ main] o.s.orm.jpa.JpaTransactionManager : Suspending current transaction, creating new transaction with name [com.ssg.WriteService.save]

현재 (부모의) 트랜잭션을 잠깐 중단하고 새 transaction을 생성합니다.

테스트

db 조회해서 저장이 다 잘 됐는지 개발자가 눈으로 직접 확인했었습니다만, 자가 검증하는 테스트를 만들어보겠습니다. (이 부분은 테스트를 이렇게도 만들어 봤다에 의의를 두고 있습니다.)

실제로 HTTP 요청이 들어오는 상황을 만들어서 테스트 하는 걸 잘 몰라서 이정도만 해보았습니다. 혹시 좋은 테스트 의견이 있으시면 알려주시면 감사하겠습니다!

@SpringBootTest
@ExtendWith(MockitoExtension.class)
class LoggingAspectTest {

    @Autowired
    private TestController controller;

    @Autowired
    private TestLoggingAspect aspect;

    @MockBean
    private WriteService writeService;
    
    @MockBean
    private ObjectProvider<TestRequestBean> provider;

    @Test
    void test2() {
        TestRequestBean testRequestBean = testBeanProvider.getObject();
        testRequestBean.setMallNm("MALL_NAME");
        testRequestBean.setAllnDiv(RequsetMarketDataBean.AllnDiv.ORDER);

        controller.test();
        verify(writeService).save("test >>> ", testRequestBean);
    }

}

통합테스트 + Mockito 사용하였고, Aspect에 WriteService와 ObjectProvider를 Mock 주입해주었습니다.

그리고 나서 비즈니스 로직이 실행되고 나서 writeService의 save() 메소드가 예상한 파라미터들로 잘 호출이 됐는지 테스트해보았습니다.

+이 부분에 대해서 어차피 @SpringBootTest 를 썼으니 DB조회해서 저장이 다 잘 됐는지 검증하는 게 더 확실한 방법이고, @DataJpaTest 사용하여 DB에 트랜잭션 정상 처리됐는지 확인해봐도 좋겠다는 의견을 받았는데요! 빠르게 단순 구현하기 위해서 위 코드로 만들었지만 실제 조회해서 확인해보는 방법이 훨씬 좋고 확실하겠습니다!

이상 제가 스프링에 배움이 짧아 하게 된 삽질들과 배운 것들을 적어보았는데요.