인텔리제이 톰캣 로그 실종 및 스프링 세션 springSessionRepositoryFilter(DelegatingFilterProxy 타입) 빈을 찾지 못하는 에러에 대한 회고

톰캣 로그 실종

• web.xml 에서 필터를 하나 수정했다.
  • DelegatingFilterProxy 타입의 springSessionRepositoryFilter 빈을 주석해제하여 이용하고 싶었다.
• 정상적으로 동작할 것 같았는데, 톰캣 초기화 과정에서 오류가 발생하고 정상적으로 톰캣이 실행되지 않았다.
  • 설상가상으로 오류는 콘솔 창에 로그로 표기되지도 않았다.

로그

18-Apr-2023 10:29:12.540 SEVERE [RMI TCP Connection(2)-127.0.0.1] org.apache.catalina.core.StandardContext.startInternal One or more Filters failed to start. Full details will be found in the appropriate container log file
18-Apr-2023 10:29:12.540 SEVERE [RMI TCP Connection(2)-127.0.0.1] org.apache.catalina.core.StandardContext.startInternal Context [] startup failed due to previous errors

• Full details will be found in the appropriate container log file 이라는데 appropriate container log file 이라는게 어디있는지 잘 몰랐다.

로그보기 해결

• tomcat/conf/logging.properties 파일을 확인해보니 CATALINA_BASE 에 로그가 있다고 나와있다.

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

1catalina.org.apache.juli.AsyncFileHandler.level = FINE
1catalina.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.AsyncFileHandler.prefix = catalina.
1catalina.org.apache.juli.AsyncFileHandler.encoding = EUC-KR

2localhost.org.apache.juli.AsyncFileHandler.level = FINE
2localhost.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.AsyncFileHandler.prefix = localhost.
2localhost.org.apache.juli.AsyncFileHandler.encoding = EUC-KR

3manager.org.apache.juli.AsyncFileHandler.level = FINE
3manager.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
3manager.org.apache.juli.AsyncFileHandler.prefix = manager.
3manager.org.apache.juli.AsyncFileHandler.encoding = EUC-KR

4host-manager.org.apache.juli.AsyncFileHandler.level = FINE
4host-manager.org.apache.juli.AsyncFileHandler.directory = ${catalina.base}/logs
4host-manager.org.apache.juli.AsyncFileHandler.prefix = host-manager.
4host-manager.org.apache.juli.AsyncFileHandler.encoding = EUC-KR

• Intellij 에서 톰캣 RUN 을 수행할 때 콘솔에 CATALINA_BASE 가 어디인지 나온다.

Using CATALINA_BASE:   "C:\Users\jks\AppData\Local\JetBrains\IntelliJIdea2022.3\tomcat\916ca8c8-fb6d-4d2c-97a1-09b4821210a5"
Using CATALINA_HOME:   "D:\tools\apache-tomcat-8.5.73"
Using CATALINA_TMPDIR: "D:\tools\apache-tomcat-8.5.73\temp"
Using JRE_HOME:        "C:\Users\jks\.jdks\corretto-1.8.0_322"
Using CLASSPATH:       "D:\tools\apache-tomcat-8.5.73\bin\bootstrap.jar;D:\tools\apache-tomcat-8.5.73\bin\tomcat-juli.jar"
Using CATALINA_OPTS:   ""

• 여러 타입의 톰캣을 사용할 수 있기 때문에 내가 설치한 tomcat 디렉토리를 직접 이용하는 것이 아니라 Intellij 의 임시폴더 아래에 만들어놓는듯 하다.
• CATALINA_BASE 디렉토리 아래의 localhost.2023-04-18.log 파일을 확인하니 에러에 대한 로그가 있다.

18-Apr-2023 10:21:29.485 SEVERE [RMI TCP Connection(2)-127.0.0.1] org.apache.catalina.core.StandardContext.filterStart Exception starting filter [springSessionRepositoryFilter]
    org.springframework.beans.factory.NoSuchBeanDefinitionException: No bean named 'springSessionRepositoryFilter' available
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanDefinition(DefaultListableBeanFactory.java:682)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getMergedLocalBeanDefinition(AbstractBeanFactory.java:1218)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:284)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
        at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1088)
        at org.springframework.web.filter.DelegatingFilterProxy.initDelegate(DelegatingFilterProxy.java:327)
        at org.springframework.web.filter.DelegatingFilterProxy.initFilterBean(DelegatingFilterProxy.java:235)
        at org.springframework.web.filter.GenericFilterBean.init(GenericFilterBean.java:236)
        at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:281)
        at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:262)
        at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:105)
        at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4607)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5258)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:753)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:727)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:695)
        at org.apache.catalina.startup.HostConfig.manageApp(HostConfig.java:1775)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:291)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
        at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
        at org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:483)
        at org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:431)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:291)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
        at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
        at com.sun.jmx.remote.security.MBeanServerAccessController.invoke(MBeanServerAccessController.java:468)
        at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
        at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
        at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1408)
        at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
        at sun.rmi.transport.Transport$1.run(Transport.java:200)
        at sun.rmi.transport.Transport$1.run(Transport.java:197)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:750)

해결 및 여기까지의 의문점

• CATALINA_BASE/localhost.날짜.log 에서 full detail 을 확인하면 되는 것이었다.
  • Intellij 로그에서 보여주면 안되는걸까? 왜 굳이 CATALINA_BASE 에 들어가서 저 로그를 봐야하는지는 의문이다.
  • Intellij 로그에서 보여주도록 설정하는 것이 있으면 좋겠다.
    • 찾아보면 있을지 모르겠는데 아직 찾아보진 않았다.

NoSuchBeanDefinitionException 문제 리뷰

• 로그를 기반으로 추적한 결과 이 에러는 스프링 세션 과 스프링 레디스 세션 에 대한 동작을 제대로 이해하지 못해서 생긴 에러였다.

문제 유발

• LettuceConnectionFactory 나 RedisTemplate 에 대한 구성정보 설정을 전부 java 파일에서 하고 싶었다.
• 스프링 context-redis-session.xml 에서 해당 빈에 대한 정보를 전부 지워버렸다.
• web.xml 에서는 DelegatingFilterProxy 타입의 springSessionRepositoryFilter 빈을 주석처리 했다.
• 이후 RedisHttpSession 이 동작하지 않는 문제가 발생했다.
• 다시 DelegatingFilterProxy 타입인 springSessionRepositoryFilter 의 주석만 해제하니 DelegatingFilterProxy 는 LettuceConnectionFactory 를 못찾아서 제대로 초기화가 안됐고 결국 org.springframework.beans.factory.NoSuchBeanDefinitionException: No bean named 'springSessionRepositoryFilter' available 에러가 발생됐던 것 같다.

문제 원인

• springSessionRepositoryFilter 는 스프링 레디스 세션 에 의해 자동으로 등록되어야 하는데, 적절히 초기화를 못하니 결국에 빈을 찾을 수 없다고 나온 것 같다. (추측)
  • 저 필터는 @EnableRedisHttpSession 애노테이션 혹은 RedisHttpSessionConfiguration 타입의 빈에서 자동으로 끌어와서 사용되는 필터였다.
    • springSessionRepositoryFilter 이름을 가진 빈을 찾아서 자동으로 등록시킨다.
    • 그래서 없으면 못찾아서 에러가 나는 것 같다.

문제 해결

• Filter 를 등록하려면 결국 자바 파일로만은 불가능하고 어차피 web.xml 파일이든 xml 파일을 하나는 건드려야 해서 그냥 .xml 로 설정하는 것을 유지하기로 했다.
  • DB 번호별 LettuceFactory, RedisTemplate 빈 생성 이후 작업부터 자바 파일에서 하기로 했다.
• 추후 알게된 건데 Spring Session 과 같이 중간에 톰캣의 구현을 바꿔치기하는 모듈을 사용하는 경우 DelegatingFilterProxy 를 추가해줘야 하는 일이 더러 있는 것 같다.