하이버네이트 튜토리얼을 보며 따라하고 있는데 SessionFactory 빈을 생성하는 과정에서 예외가 발생하면서 아래와 같은 스택을 뿌리며 생성에 실패한다.
Caused by: java.util.MissingFormatArgumentException: Format specifier '%s'
at java.util.Formatter.format(Formatter.java:2519) ~[na:1.8.0_25]
at java.util.Formatter.format(Formatter.java:2455) ~[na:1.8.0_25]
at java.lang.String.format(String.java:2927) ~[na:1.8.0_25]
at org.jboss.logging.Slf4jLocationAwareLogger.doLogf(Slf4jLocationAwareLogger.java:81) ~[jboss-logging-3.1.3.GA.jar:3.1.3.GA]
at org.jboss.logging.Logger.debugf(Logger.java:553) ~[jboss-logging-3.1.3.GA.jar:3.1.3.GA]
at org.hibernate.annotations.common.util.StandardClassLoaderDelegateImpl.classForName(StandardClassLoaderDelegateImpl.java:53) ~[hibernate-commons-annotations-4.0.4.Final.jar:4.0.4.Final]
at org.hibernate.cfg.annotations.SimpleValueBinder.fillSimpleValue(SimpleValueBinder.java:491) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.SetSimpleValueTypeSecondPass.doSecondPass(SetSimpleValueTypeSecondPass.java:42) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.processSecondPassesOfType(Configuration.java:1470) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.secondPassCompile(Configuration.java:1418) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1844) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1928) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.springframework.orm.hibernate4.LocalSessionFactoryBuilder.buildSessionFactory(LocalSessionFactoryBuilder.java:372) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.orm.hibernate4.LocalSessionFactoryBean.buildSessionFactory(LocalSessionFactoryBean.java:454) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.orm.hibernate4.LocalSessionFactoryBean.afterPropertiesSet(LocalSessionFactoryBean.java:439) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1633) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1570) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'requestHistoryDao': Injection of autowired dependencies failed; nested exception is org.springframework.beans.factory.BeanCreationException: Could not autowire field: private org.hibernate.SessionFactory io.csb.pigeon.api.dao.impl.AbstractDao.sessionFactory; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sessionFactory' defined in io.csb.pigeon.api.configuration.HibernateConfiguration: Invocation of init method failed; nested exception is java.util.MissingFormatArgumentException: Format specifier '%s'
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:334) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1210) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:537) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:755) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:757) ~[spring-context-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480) ~[spring-context-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:663) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:629) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:677) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:548) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:489) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136) [spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at javax.servlet.GenericServlet.init(GenericServlet.java:158) [servlet-api.jar:3.1.FR]
at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1231) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1144) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1031) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4909) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5196) [catalina.jar:8.0.20.B]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardContext.reload(StandardContext.java:3746) [catalina.jar:8.0.20.B]
at org.apache.catalina.loader.WebappLoader.backgroundProcess(WebappLoader.java:292) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5523) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1378) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1382) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1382) [catalina.jar:8.0.20.B]
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1350) [catalina.jar:8.0.20.B]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_25]
Caused by: org.springframework.beans.factory.BeanCreationException: Could not autowire field: private org.hibernate.SessionFactory io.csb.pigeon.api.dao.impl.AbstractDao.sessionFactory; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sessionFactory' defined in io.csb.pigeon.api.configuration.HibernateConfiguration: Invocation of init method failed; nested exception is java.util.MissingFormatArgumentException: Format specifier '%s'
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:561) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:88) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessPropertyValues(AutowiredAnnotationBeanPostProcessor.java:331) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
... 31 common frames omitted
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sessionFactory' defined in io.csb.pigeon.api.configuration.HibernateConfiguration: Invocation of init method failed; nested exception is java.util.MissingFormatArgumentException: Format specifier '%s'
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1574) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:539) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.findAutowireCandidates(DefaultListableBeanFactory.java:1120) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1044) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:942) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:533) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
... 33 common frames omitted
Caused by: java.util.MissingFormatArgumentException: Format specifier '%s'
at java.util.Formatter.format(Formatter.java:2519) ~[na:1.8.0_25]
at java.util.Formatter.format(Formatter.java:2455) ~[na:1.8.0_25]
at java.lang.String.format(String.java:2927) ~[na:1.8.0_25]
at org.jboss.logging.Slf4jLocationAwareLogger.doLogf(Slf4jLocationAwareLogger.java:81) ~[jboss-logging-3.1.3.GA.jar:3.1.3.GA]
at org.jboss.logging.Logger.debugf(Logger.java:553) ~[jboss-logging-3.1.3.GA.jar:3.1.3.GA]
at org.hibernate.annotations.common.util.StandardClassLoaderDelegateImpl.classForName(StandardClassLoaderDelegateImpl.java:53) ~[hibernate-commons-annotations-4.0.4.Final.jar:4.0.4.Final]
at org.hibernate.cfg.annotations.SimpleValueBinder.fillSimpleValue(SimpleValueBinder.java:491) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.SetSimpleValueTypeSecondPass.doSecondPass(SetSimpleValueTypeSecondPass.java:42) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.processSecondPassesOfType(Configuration.java:1470) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.secondPassCompile(Configuration.java:1418) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1844) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1928) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.springframework.orm.hibernate4.LocalSessionFactoryBuilder.buildSessionFactory(LocalSessionFactoryBuilder.java:372) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.orm.hibernate4.LocalSessionFactoryBean.buildSessionFactory(LocalSessionFactoryBean.java:454) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.orm.hibernate4.LocalSessionFactoryBean.afterPropertiesSet(LocalSessionFactoryBean.java:439) ~[spring-orm-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1633) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1570) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
... 43 common frames omitted
구글링으로 예외와 관련한 것들을 찾아보다가, 비슷한 유형이 나타나지 않길래 라이브러리 내에서 어떤 부분이 문제인지를 확인하려고 org.hibernate.annotations.common.util.StandardClassLoaderDelegateImpl 클래스를 따라가보니 아래 부분에서 예외가 발생했다.
catch ( Throwable ignore ) {
log.debugf( "Unable to locate Class [%s] using TCCL, falling back to HCANN ClassLoader" );
}
빨간색으로 표기한 %s에 전달되어야 할 문자열을 전달하지 않아서 발생하는 예외였다. 실수는 할 수 있지만.. 유틸리티성 클래스라 테스트 커버리지에 포함되지 않아서인지 릴리즈에 버젓이 나 버그요 어디 한번 실행해 보시지 하는 태도라니.
이는 하이버네이트 ORM 4.3.5.Final 버전에서 발생하며, 이 후 버전에서는 고쳐진 듯 하다. (4.3.10.Final 버전으로 확인하니 예외가 발생하지 않는다.)
사실 상용 프레임워크나 소프트웨어는 거의 사용하지 않고 오픈 소스를 주로 이용하다보니, 검증없이 신뢰하기 마련인데, 이번 계기로 모든 것에 의심을 가지자는 태도를 다시 갖춰야겠다.
아마 Moneycomb 프로젝트를 할 때였던 것 같다. 나는 그때도 JSON으로 메시지를 변환하기 위해, 책과 튜토리얼에서 빈번하게 등장하고, 다들 문제없이 쓰는 것으로 보이던 MappingJacksonHttpMessageConverter를 '나도 당연히 되겠지?' 하며 튜토리얼들을 따라 서블릿 컨텍스트에 빈을 설정했다.
지옥의 시작
왜인가? 어째서인가? 남들 다 된다고 댓글에도 "Thank you!"가 넘치고, 누구하나 되지 않는다는 이 없는데, 나는 왜 안되는 것인가.
지금도 그렇지만 그 때에도 Google의 JSON 라이브러리인 Gson을 즐겨썼다. API가 복잡하지 않고 설정도 간단했기 때문이다.
하지만 스프링에서 기본적으로 제공하는 JSON 메시지 컨버터는 Jackson에 의존성이 있었는데, 일단 Jackson이라는 라이브러리 자체가 낯설었고, 스프링 MVC의 동작을 깊이 파악하고 있지 않았던 탓에 하라는 대로 하는 것 외에는 손대볼 수 있는게 없었다.
열심히 설정하고 코드를 따라서 친 후 실행, 두근거리는 마음으로 Postman으로 메시지를 날려보았다.
@RequestBody 애너테이션이 붙어있는 파라미터에서도 변환이 되질 않고, @ResponseBody 애너테이션이 붙어있는 파라미터에서도 변환이 되질 않는다.
이때는 log4j 설정도 잘 몰라서, 콘솔에서는 어떠한 로그도 뜨지 않길래, 스프링이 아무말 없이 응답으로만 "안돼"라고 하는 줄로만 알았다.
Content-Type, Accept
스프링 컨트롤러에서 @RequestMapping 애노테이션에는 Content-Type과 Accept를 설정할 수 있는 consumes와 produces 속성이 있다. JSON의 미디어 타입이 application/json 인 것은 웹 하는 사람이라면 누구라도 알고 있을 것이다.
튜토리얼에서는 명시적으로 지정해주지 않았지만, 안되길래 consumes와 produces에 "application/json"이라고 적어주었다. 안된다. 이게 문제가 아닌가보다.
오늘도 삽질
그 때와 똑같은 행태를 반복해서였는지는 모르겠지만 오늘도 똑같은 현상이 나타났다. JSON 직렬화도, 역직렬화도 안된다.
그 때는 해결하지 못했던 문제였지만 오늘은 나름 해결을 하긴 했다.
여러가지 오해와 착각과 습관과 편견과 게으름의 결과였던 듯 하다.
1. 반환 타입
다른 테스트 클래스를 만들거나 모델 클래스를 반환하려니 값을 넣기도 귀찮아서
@RequestMapping(....)
@ResponseBody
public Object test(@RequestBody ....) { ... }
위 처럼 Object를 반환했다. JSON 자체에서도 { } 라고 쓰기도 하거니와, Gson에서는 Object 객체도 잘 변환한다. 빈 객체를 표현할 수도 있으니 당연하다고 생각했는데, Jackson에서는 Object 객체를 JSON으로 직렬화할 수 없다.
"Can not create bean serializer for Object.class" 란다. 어떤 정책으로 인해서 이렇게 정해졌는지는 알 수 없지만, 이것 때문에 한방.
2. 테스트 Ajax 요청
테스트로 JSON 객체를 보낼 때도, 필드 몇 개를 대충 보내거나 했는데, 이 전 버전의 Jackson(codehaus)은 JSON에는 있지만 변환될 자바 타입에서 없는 속성, 빈 문자열은 변환할 수 없고 예외를 발생시킨다.
애초에 테스트 JSON 문자열을 잘 썼으면 문제가 없었을지도 모르지만... 이 역시 Gson을 쓰면서 Gson이 동작하는 대로 생각해서 였던 것 같다. Gson에서는 없는 프로퍼티는 무시하고, 빈 JSON 문자열의 경우 null을 반환한다.
어쨌든 이번 일로 인해 좀 더 MessageConverter의 동작을 명확히 알게 되었고, 더불어 아래와 같은 것 잡지식(?)이 늘었다.
- com.fasterxml.jackson은 org.codehaus.jackson를 승계한 프로젝트