1. 개요
고통은 왜 몰아서 오는것일까.
웹어드민 애플리케이션에 CD파이프라인을 적용했더니, 일부api에서 404 not found가 발생했다. 로컬에서 빌드한 war를 기동하면 전체 api가 정상인데, CI/CD를 통해서 빌드된 war에서만 해당 현상이 발생하는 재밌는 상황이었다.
원인을 찾기 위해 하루를 꼬박 삽질한 것 같다.
메이븐 옵션에, 서버 jetty버전도 맞춰보고 ci/cd가 작동하는 도커 이미지도 변경해봤지만 모두 동일했다. 일부 api는 정상 작동하므로 was설정 문제도 아니었고, 정상 동작하는 controller와 404 controller를 비교해봐도 특이점은 확인되지 않았다.
결국 jetty로그를 아예 trace레벨로 낮추고, 오동작하는 war파일을 기동해 정상 동작하는 api와 오동작하는 api의 로그를 비교한 끝에 원인을 파악할 수 있었다.
2. 로그를 분석하자
2.1. 정상 작동하는 api로그
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[DEBUG][2021-10-12 15:26:14,280] DefaultSingletonBeanRegistry.java:225(main) - Creating shared instance of singleton bean 'menuController'
[TRACE][2021-10-12 15:26:14,280] AbstractAutowireCapableBeanFactory.java:489(main) - Creating instance of bean 'menuController'
[TRACE][2021-10-12 15:26:14,280] AbstractAutowireCapableBeanFactory.java:592(main) - Eagerly caching bean 'menuController' to allow for resolving potential circular references
[TRACE][2021-10-12 15:26:14,280] AbstractBeanFactory.java:264(main) - Returning cached instance of singleton bean 'menuService'
[TRACE][2021-10-12 15:26:14,280] AutowiredAnnotationBeanPostProcessor.java:586(main) - Autowiring by type from bean name 'menuController' to bean named 'menuService'
[DEBUG][2021-10-12 15:26:14,281] DelegatingMethodSecurityMetadataSource.java:76(main) - Caching method [CacheKey[kello.web.controller.MenuController; public java.util.List kello.web.controller.MenuController.menus()]] with attributes [MenuSecurityConfig(menus=[MNU01], readonly=true)]
[TRACE][2021-10-12 15:26:14,281] AbstractAutoProxyCreator.java:539(main) - Creating implicit proxy for bean 'menuController' with 0 common interceptors and 1 specific interceptors
[TRACE][2021-10-12 15:26:14,281] CglibAopProxy.java:162(main) - Creating CGLIB proxy: SingletonTargetSource for target object [kello.web.controller.MenuController@1478ffd7]
[TRACE][2021-10-12 15:26:14,281] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public java.util.List kello.web.controller.MenuController.menus()
[DEBUG][2021-10-12 15:26:14,281] DelegatingMethodSecurityMetadataSource.java:76(main) - Caching method [CacheKey[kello.web.controller.MenuController; public kello.web.domain.Menu kello.web.controller.MenuController.menu(kello.web.domain.Menu)]] with attributes [MenuSecurityConfig(menus=[MNU01], readonly=true)]
[TRACE][2021-10-12 15:26:14,281] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public kello.web.domain.Menu kello.web.controller.MenuController.insert(kello.web.domain.Menu)
[DEBUG][2021-10-12 15:26:14,281] DelegatingMethodSecurityMetadataSource.java:76(main) - Caching method [CacheKey[kello.web.controller.MenuController; public int kello.web.controller.MenuController.update(kello.web.jpa.entity.Menu)]] with attributes [MenuSecurityConfig(menus=[MNU01], readonly=false)]
[TRACE][2021-10-12 15:26:14,282] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public int kello.web.controller.MenuController.update(kello.web.jpa.entity.Menu)
[TRACE][2021-10-12 15:26:14,285] ScheduledAnnotationBeanPostProcessor.java:368(main) - No @Scheduled annotations found on bean class: class kello.web.controller.MenuController
[TRACE][2021-10-12 15:26:14,285] AbstractAutowireCapableBeanFactory.java:526(main) - Finished creating instance of bean 'menuController'
[TRACE][2021-10-12 15:26:15,246] AbstractHandlerMethodMapping.java:291(main) -
b.w.c.MenuController:
{GET [/api/menus]}: menus()
{POST [/api/menu]}: insert(Menu)
{PUT [/api/menu]}: update(Menu)
[DEBUG][2021-10-12 15:26:15,252] AbstractHandlerMethodMapping.java:363(main) - 98 mappings in 'requestMappingHandlerMapping'
기동 후 정상적으로 작동한 MenuController의 로그이다.
DefaultSingleBeanRegistry에서 MenuController 빈을 생성하고 있으며, AbstractAutowireCapableBeanFactory에서는 MenuController에서 참조하고 있는 서비스인 MenuService를 찾아 autowiring을 수행한 것을 확인할 수 있다.
그리고 CglibAopProxy를 통해 프록시를 생성하고, 생성된 인스턴스는 AbstractHandlerMethodMapping에서 실제 유저의 요청에 대응할 수 있도록 있도록 매핑된다.
2.2. 비정상 작동하는 api로그
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
[DEBUG][2021-10-12 15:26:13,311] DefaultSingletonBeanRegistry.java:225(main) - Creating shared instance of singleton bean 'flowController'
[TRACE][2021-10-12 15:26:13,311] AbstractAutowireCapableBeanFactory.java:489(main) - Creating instance of bean 'flowController'
[TRACE][2021-10-12 15:26:13,312] AbstractAutowireCapableBeanFactory.java:592(main) - Eagerly caching bean 'flowController' to allow for resolving potential circular references
[TRACE][2021-10-12 15:26:13,312] AbstractBeanFactory.java:264(main) - Returning cached instance of singleton bean 'flowService'
[TRACE][2021-10-12 15:26:13,312] AutowiredAnnotationBeanPostProcessor.java:586(main) - Autowiring by type from bean name 'flowController' to bean named 'flowService'
[TRACE][2021-10-12 15:26:13,313] CglibAopProxy.java:162(main) - Creating CGLIB proxy: SingletonTargetSource for target object [kello.web.controller.FlowController@3e929c9c]
[TRACE][2021-10-12 15:26:13,314] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public kello.web.domain.ui.FlowInformationDetail kello.web.controller.FlowController.flows()
[TRACE][2021-10-12 15:26:13,314] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public int kello.web.controller.FlowController.insert(kello.web.jpa.entity.Flow)
[TRACE][2021-10-12 15:26:13,314] CglibAopProxy.java:897(main) - Unable to apply any optimizations to advised method: public int kello.web.controller.FlowController.update(kello.web.jpa.entity.Flow)
[DEBUG][2021-10-12 15:26:13,319] DelegatingMethodSecurityMetadataSource.java:76(main) - Caching method [CacheKey[kello.web.controller.FlowController$$EnhancerBySpringCGLIB$$a448a1f5; public int kello.web.controller.FlowController.flows()]] with attributes [MenuSecurityConfig(menus=[MNU005], readonly=false)]
[TRACE][2021-10-12 15:26:13,319] AbstractAutoProxyCreator.java:539(main) - Creating implicit proxy for bean 'flowController' with 0 common interceptors and 1 specific interceptors
[TRACE][2021-10-12 15:26:13,319] JdkDynamicAopProxy.java:124(main) - Creating JDK dynamic proxy: SingletonTargetSource for target object [kello.web.controller.FlowController$$EnhancerBySpringCGLIB$$a448a1f5@597edc92]
[TRACE][2021-10-12 15:26:13,320] ScheduledAnnotationBeanPostProcessor.java:368(main) - No @Scheduled annotations found on bean class: class kello.web.controller.FlowController
[TRACE][2021-10-12 15:26:13,320] AbstractAutowireCapableBeanFactory.java:526(main) - Finished creating instance of bean 'flowController'
[DEBUG][2021-10-12 15:26:15,252] AbstractHandlerMethodMapping.java:363(main) - 98 mappings in 'requestMappingHandlerMapping'
이건 404가 발생한 flowController의 로그이다.
menuController와 마찬가지로 DefaultSingleBeanRegistry에서 빈을 생성했고, AbstractAutowireCapableBeanFactory에서는 참조하고 있는 서비스를 찾아 autowiring해주었다.
그리고 CglibAopProxy를 통해 프록시도 생성했다.
여기까지만 보면 빈 생성 및 프록시 생성까지는 제대로 처리한 것 같아보인다. 그러나 차이점은 그 아래에 있었다.
먼저, 17라인을 보면 JdkDynamicAopProxy에서 FlowController를 Jdk dynamic proxy로 생성한 것을 확인할 수 있다. 그 후 menuController와 마찬가지로 AbstractHandlerMethodMapping에서 매핑이 진행되어야 했는데, 관련 로그가 남아있지 않았다.
그리고 마지막에는 98건이 mapping됐다고 로그가 남아있는데, 사실 567건이 mapping되어야 정상이다.
빈은 성공적으로 생성되었으나 dispatcher servlet이 생성되면서 정상적으로 매핑되어야 했을 api들이 덜 매핑된 것이다. 그리고 매핑되지 않은 api들은 jdk dynamic proxy로 생성된 빈들이었음을 확인할 수 있었다.
3. Cglib proxy? Jdk proxy?
그렇다면 Cglib proxy, Jdk dynamic proxy가 대체 뭘까?
먼저, Cglib proxy나 Jdk dynamic proxy는 실제 코드를 수정하지 않으면서 바이트코드에 기능을 추가할 수 있는 기능이다. 이러한 이점때문에 spring에서는 AOP를 구현할 때 해당 기능들을 사용하고 있다.
AOP(Aspect-Oriented Programming)는 프로그램 구조에 대한 다른 방식을 제공하여 OOP(Object-oriented Programming)를 보완한다. OOP의 핵심 모듈이 클래스라면, AOP의 핵심 모듈은 측면(aspect)이다. Aspect는 트랜잭션 관리와 같은 다양한 타입과 오브젝트를 가로지르는 모듈화를 가능하게 한다. (Aspect Oriented Programming with Spring)
3.1. 프록시 메커니즘
Spring AOP는 Jdk dynamic proxy 혹은 Cglib를 사용해 타겟 오브젝트에 대한 프록시를 생성한다.
Jdk dynamic proxy는 jdk에 기본적으로 내장되어 있는 반면, Cglib는 별도의 오픈소스로 구현되어 있으며 이는 Spring 3.2부터 spring core jar에 포함되어 있다.
만약 오브젝트가 하나 이상의 인터페이스를 구현했다면 Jdk dynamic proxy를 사용하며, 인터페이스를 구현하지 않았다면 Cglib proxy를 사용한다.
결론적으로 Jdk dynamic proxy 혹은 Cglib proxy 모두 위와 같은 방식으로 요청이 되며, 성능 차이는 거의 없다고 스프링 측에서는 설명하고 있다.
pojo.foo()를 요청했을 때, 바로 요청하는 것이 아니라 Proxy가 대신 pojo.foo()를 요청하면서 foo메소드가 실행되기 전후로 작업하고 싶은 기능을 추가할 수 있다.
단, Jdk dynamic proxy로 생성된 오브젝트는 사용 시에 인터페이스를 이용해 사용해야한다. 마찬가지로 DI도 인터페이스로 타입을 지정해 주입받지 않으면 DI시 실패하게 된다.
3.2. 그래서 프록시가 404랑 무슨 상관이지?
Spring mvc는 모든 api의 요청/응답을 Dispatcher servlet를 통해 처리한다.
이를 위해 기동 시 Dispatcher servlet을 생성하는데, dispatcher servlet은 내부적으로 클라이언트 요청이 있을 때 응답해야하는 api를 HandlerMapping오브젝트 형태의 리스트로 가지고 있게 된다.
이 HandlerMapping리스트는 initHandlerMappings메소드에서 RequestMappingHandlerMapping클래스를 통해 매핑할 api들을 찾는데, 이 때 BeanFactoryUtils클래스의 beansOfTypeIncludingAncestors메소드를 사용한다.
등록한 빈이 저장돼있는 ListableBeanFactory에서 HandlerMapping클래스 타입의 빈들은 모두 가져와 등록하는데, 이 때 Jdk dynamic proxy로 생성된 빈들은 찾지 못하는 것으로 보인다. (빈팩토리에 등록할 때 원래 빈이 아닌 프록시 자체를 등록하나 추측 중)
4. 해결
따라서 해결책은 Jdk dynamic proxy대신 Cglib proxy를 사용하도록 강제하는 데에 있었다.
아래의 방법으로 인터페이스를 구현한 경우에도 Cglib proxy를 사용하도록 설정해줄 수 있다. 난 4.2의 방법으로 해결할 수 있었다.
4.1. Aop설정 변경
<aop:config proxy-target-class="true">
<!-- other beans defined here... -->
</aop:config>
4.2. Aspectj 자동 프록시를 사용하는 경우
<aop:aspectj-autoproxy proxy-target-class="true"/>
4.3. Controller클래스에 어노테이션 추가
@Scope( proxyMode = ScopedProxyMode.TARGET_CLASS )
5. 결론
사실 이렇게 해결은 했지만, 아직 미스테리인 부분이 있다.
위에서도 언급했듯이 Jdk dynamic proxy는 인터페이스를 구현한 오브젝트에서 동작하는데, 404가 발생한 controller들은 인터페이스를 구현한 클래스가 아니었다.
또한, 로컬에서 빌드한 war파일은 모두 Cglib proxy를 사용하는 반면, ci/cd파이프라인을 통해 생성된 war만 일부 api를 Jdk dynamic proxy로 처리한 것이다.
관련해서 계속 구글링해봤으나 이에 관련된 레퍼런스는 찾을 수 없었고, 현재 위와 같이 해결한 상태로 남아있다. 이 부분은 추가적으로 레퍼런스를 발견하게 되면 추가 포스팅 예정이다.