ologist`s story

어느날 갑자기 개발장비에 있는 mq를 restart를 하는데 java.io.UTFDataFormatException가 발생을 하면서 제대로 올라가지 않았다.

몇가지 의심을 해보았다.
- production branch와 코드가 다른 것이 있는가?
- 설정파일에 인코딩 문제가 있나?
- 윈도우와 리눅스 머신 둘다 잘 안되는가?

첫번째 compare를 해서 다른 branch간에 차이점을 찾았지만, 없었다...-.-

설정파일을 열어보면 영어이외에 다른 멀티바이트 문자가 존재하지 않았다. (이거 파일의 인코딩 문제도 아니잖아!)

로컬 윈도우에서 mq를 올려봤다 잘 올라간다. 그럼 윈도우에서는 되고, 리눅스에서는 안되는건가? 아니다. 다른 개발장비의 리눅스머신에서는 잘되고 있다.

환경설정 문제가 아닐까 생각을 하면서 일단 접고 운동을 하고 집에 갔다. 다음날 아침에 mq를 처음에 설치한 사람이 있어서 도움을 요청했다. 역시 만족할만한 힌트를 얻었고, 처리를 했다.

mq는 서비스가 내려갈때 file DB를 사용하게 되어있는데, 잘못된 타입(인코딩?)의 글자로 인코딩이 되어서 내려간거 같다. mq가 올라가면서 Unmarshal을 하는데 예외가 발생을 한것이였다.

언제 이런 상황이 발생을 하는지 알수 없었다. 개발장비라 난잡한 상황이 자주 발생을 하기 때문에 이 원인을 찾는 것도 쉽지 않은 일이다. 내가 처리한 방법은  저장된 파일을 모두 제거를 하고 mq를 띄우니 제대로 컨텍스트가 올라갔다.

근본적인 원인을 찾진 못했지만, 문제가 된 부분을 제거할 수는 있었다.

아래는 에러로그를 캡쳐했다. 로그를 볼때 주의 깊게 봐야 하는데, 이번에 놓친 부분은 ERROR나기전에 나오는 INFO레벨의 로그이다. 이 부분을 잘보면 무엇을 하다가 예외가 발생을 했는지 살펴보기 좀더 쉽다.
 
로그를 통해서 lifecycle을 살펴보면 Broker서비스가 올라갈때 기존에 정의된 파일 위치에서 읽어서 메모리로 복구를 시도를 한다. 이 부분에서 문제가 생겨서 Broker서비스자체가 올라가는데 실패를 한 것이다.

이번건을 처리하면서 잊었던 기억하나는 대부분의 문제의 해결방법은 로그에 거의 있다는 것이다. 좀더 로그가 친절했으면 좋을뻔했지만, 상황만 더 이해를 했다면 쉽게 찾을 수 있는 문제였다.

잘되는 것과 안되는 것이 있으면 차이점을 빠르게 파악을 해서 의심의 범위를 줄이는 것도 중요하다. 이 경우 많은 삽질을 하게 되는데 그 공수를 줄이는 것이 중요하다. 그때 매뉴얼과 로그는 문제해결의 둘도 없는 친구이다. 로그의 중요성을 다시 한번 되새긴 경험이었다...^^

2008-05-13 20:00:12 [INFO ](JournalPersistenceAdapter.java:464) Journal Recovery Started from: Active Journal: using 5 x 20.0 Megs at: /env/activemq/activemq-data/journal
2008-05-13 20:00:12 [ERROR](BrokerService.java:412) Failed to start ActiveMQ JMS Message Broker. Reason: java.io.UTFDataFormatException: bad string
java.io.UTFDataFormatException: bad string
        at org.apache.activemq.util.DataByteArrayInputStream.readUTF(DataByteArrayInputStream.java:286)
        at org.apache.activemq.openwire.v2.BaseDataStreamMarshaller.looseUnmarshalString(BaseDataStreamMarshaller.java:536)
        at org.apache.activemq.openwire.v2.ProducerIdMarshaller.looseUnmarshal(ProducerIdMarshaller.java:119)
        at org.apache.activemq.openwire.OpenWireFormat.looseUnmarshalNestedObject(OpenWireFormat.java:445)
        at org.apache.activemq.openwire.v2.BaseDataStreamMarshaller.looseUnmarsalCachedObject(BaseDataStreamMarshaller.java:454)
        at org.apache.activemq.openwire.v2.MessageIdMarshaller.looseUnmarshal(MessageIdMarshaller.java:119)
        at org.apache.activemq.openwire.OpenWireFormat.looseUnmarshalNestedObject(OpenWireFormat.java:445)
        at org.apache.activemq.openwire.v2.BaseDataStreamMarshaller.looseUnmarsalNestedObject(BaseDataStreamMarshaller.java:436)
        at org.apache.activemq.openwire.v2.MessageAckMarshaller.looseUnmarshal(MessageAckMarshaller.java:133)
        at org.apache.activemq.openwire.OpenWireFormat.looseUnmarshalNestedObject(OpenWireFormat.java:445)
        at org.apache.activemq.openwire.v2.BaseDataStreamMarshaller.looseUnmarsalNestedObject(BaseDataStreamMarshaller.java:436)
        at org.apache.activemq.openwire.v2.JournalQueueAckMarshaller.looseUnmarshal(JournalQueueAckMarshaller.java:117)
        at org.apache.activemq.openwire.OpenWireFormat.doUnmarshal(OpenWireFormat.java:349)
        at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:204)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.recover(JournalPersistenceAdapter.java:470)
        at org.apache.activemq.store.journal.JournalPersistenceAdapter.start(JournalPersistenceAdapter.java:225)
        at org.apache.activemq.broker.BrokerService.createRegionBroker(BrokerService.java:1251)
        at org.apache.activemq.broker.BrokerService.createBroker(BrokerService.java:1209)
        at org.apache.activemq.broker.BrokerService.getBroker(BrokerService.java:508)
        at org.apache.activemq.broker.BrokerService.start(BrokerService.java:394)
        at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:47)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1201)