[JAVA][기본]error log분석 스택트레이스(stack trace) 분석해라

널포인터 예외(NullPointerException)의 원인을 찾는 문제인데, 이슈트래커에서 해당하는 스택트레이스(stack trace)와 해당하는 소스 파일을 보여주고 원인을 추적해보게 하는 테스트입니다.

처음보는 다른 사람이 짠 소스를 어떻게 분석할 수 있을까 의아할 수 있지만, 실제로 널포인터 예외는 개발중에 매우 흔히 경험하는 오류이고 특성상 정확한 의미만 알고 있다면 거의 대부분 즉시 정확한 원인을 분석할 수 있습니다. 또한 그러기 위해서는 스택트레이스를 읽을 수 있는 능력이 필요합니다.

개인적으로 예외 처리는 초보 개발자가 가장 중요성을 간과하기 쉬운 분야라고 생각합니다. 예외처리라고 하면 단순하게 '그냥 try-catch하면 되는 게 아닌가?'라고 쉽게 생각할 수도 있지만 사실 이야기를 하자면 상당한 설계 차원의 지식이 필요한 문제가 예외처리입니다. 초보 개발자 분들이라면 그렇게 깊게까지 파고들 필요는 없겠지만 최소한 스택트레이스는 정확히 읽을 줄 알아야지만 빠른 디버깅이 가능한 만큼 이 부분에 대해서만은 시간을 투자해서 정확한 지식을 쌓아둘 필요가 있다고 생각합니다.

제시한 스택 트레이스는 이렇습니다 :

java.lang.reflect.InvocationTargetException
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at com.droplets.ap.xul.builder.handler.MethodCallback.invokeCallback(MethodCallback.java:32)
     at com.droplets.ap.xul.builder.handler.ViewHandler.invokeActionResult(ViewHandler.java:581)
     at com.droplets.ap.xul.context.impl.ViewContextImpl$2.onActionResult(ViewContextImpl.java:283)
     at com.droplets.ap.xul.context.impl.ActionContextImpl.setResult(ActionContextImpl.java:90)
     at com.droplets.ap.xul.action.stock.DialogAction.handleDialogClose(DialogAction.java:156)
     at com.droplets.ap.xul.action.stock.DialogAction$1.windowClosed(DialogAction.java:142)
     at com.droplets.api.Window.fireWindowClosedEvent(Unknown Source)
     at com.droplets.api.Window.onClose(Unknown Source)
     at com.droplets.api.platform.WindowBase.BaseClose(Native Method)
     at com.droplets.api.platform.WindowBase.BaseClose(Unknown Source)
     at com.droplets.api.Window.close(Unknown Source)
     at com.droplets.ap.xul.ui.MessageDialog.handleButtonClick(MessageDialog.java:145)
     at com.droplets.ap.xul.ui.MessageDialog$1.handleClick(MessageDialog.java:134)
     at com.droplets.api.ClickableSupport.fireClickEvent(Unknown Source)
     at com.droplets.api.ClickableSupport.handleAction(Unknown Source)
     at com.droplets.api.Button.actionHook(Unknown Source)
     at com.droplets.api.Component.action(Unknown Source)
Caused by: java.lang.NullPointerException
     at com.eyeq.kona.service.impl.PortalManagerImpl.deleteMenuItem(PortalManagerImpl.java:603)
     at com.eyeq.kona.service.impl.PortalManagerImpl.deletePortal(PortalManagerImpl.java:358)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
     at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
     at org.springframework.security.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:66)
     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
     at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
     at $Proxy54.deletePortal(Unknown Source)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
     at java.lang.reflect.Method.invoke(Unknown Source)
     at com.eyeq.kona.util.SpringSecurityContextInvocationHandler.invoke(SpringSecurityContextInvocationHandler.java:62)
     at $Proxy84.deletePortal(Unknown Source)
     at com.eyeq.kona.ui.binding.PortalDataProvider.doDelete(PortalDataProvider.java:81)
     at com.eyeq.kona.ui.binding.PortalDataProvider.doDelete(PortalDataProvider.java:12)
     at com.eyeq.kona.ui.binding.AbstractEISDataProvider.delete(AbstractEISDataProvider.java:105)
     at com.droplets.ap.xul.binding.dataset.impl.DatasetImpl.doCommit(DatasetImpl.java:90)
     at com.droplets.ap.xul.binding.dataset.impl.AbstractDataset.commit(AbstractDataset.java:251)
     at com.droplets.ap.xul.binding.dataset.impl.AbstractDataset.deleteRow(AbstractDataset.java:201)
     at com.droplets.ap.xul.action.dataset.DeleteDataRowAction.execute(DeleteDataRowAction.java:22)
     at com.droplets.ap.xul.context.impl.ViewContextImpl.execute(ViewContextImpl.java:294)
     at com.eyeq.kona.ui.portal.PortalInfoHandler.onPostConfirmDeleteAction(PortalInfoHandler.java:192)
     ... 21 more

상당히 길죠? 제가 본 많은 수의 초보 개발자분들은 이런 로그를 접하면 지례 겁을 먹고 정확하게 트레이스를 읽으려 들지 않습니다. 'java.lang.NullPointerException'이란 부분만 확인하거나 심지어 아예 예외처리에서 조차 e.printStackTrace()를 하는 대신 System.err.println("Error!")하는 식으로 디버깅할 때 무엇보다 중요한 정보인 스택 트레이스를 무시해버리는 경우도 있습니다.

그리고는 보통 '왜 책에서 본대로 쳤는데 안되는 거지?'내지는 '왜 어제까지 되던게 에러가 나는 걸까. 내가 뭘 고쳤지?'하는 식으로 어림짐작에 의해 문제를 해결하려 애쓰기도 합니다.

예외처리를 제대로 작성한 코드라면 거의 대부분의 문제는 스택트레이스 안에 답이 있습니다.

우선 위의 예의 경우 트레이스가 두 가지 예외 내용을 포함하고 있다는 것을 바로 파악할 수 있어야 하며, 문제의 진정한 원인은 윗쪽의 트레이스가 아니라 'Caused By:'로 표시되는 널포인터 예외 부분임을 인지할 수 있어야 합니다.

일단 문제에 대한 원인이 되는 트레이스를 찾았다면 그 다음은 트레이스를 읽어야 하는데, 이제까지 꽤 많은 수의 초급 개발자들의 면접을 경험했지만 의외로 트레이스 읽는 법을 정확하게 아는 경우가 드물었습니다. 면접시 위의 트레이스를 보여주고 어쩔 줄 몰라할 경우 보통 힌트를 주고 예를들어 널포인터 예외가 찍힌 부분부터 아래쪽으로 단 세줄만 집중해서 무슨 뜻인지 해석해보라고 질문합니다. 즉,

Caused by: java.lang.NullPointerException

     at com.eyeq.kona.service.impl.PortalManagerImpl.deleteMenuItem(PortalManagerImpl.java:603)
     at com.eyeq.kona.service.impl.PortalManagerImpl.deletePortal(PortalManagerImpl.java:358)

이 부분을 보여주고 읽는 방법을 알고 있는지 묻는 질문인데, 이를 정확하게 'com.eyeq.kona.service.impl.PortalManagerImpl 클래스의 deletePortal 메소드 358라인에서 같은 클래스 deleteMenuItem메소드를 호출했는데 해당 메소드 603라인에서 널포인터 예외가 발생했다'라고 해석할 수 있는 지원자가 많지 않았습니다.

아예 대답을 못하거나 트레이스를 위에서 아래로 해석하려 하거나 심지어 이를 '두 번의 널포인터 예외가 발생했다'로 해석하는 경우까지 있더군요. 이런 로그를 보고 곧바로 해당 클래스의 603라인을 찾아갈 수 있는 개발자와 '내가 뭘 잘못 쳐서 안되는 거지?' 하는 식으로 막연한 고민으로 시간을 허비하는 개발자를 상상해보시면 스택트레이스를 정확히 아는 것이 얼마나 디버깅과 관련한 개발생산성에 큰 도움을 주는 지 짐작 가능하시리라 생각합니다.

그리고 해당 부분, 즉 PortalManagerImpl 클래스의 603라인의 소스는 다음과 같았습니다 (굵은 글씨 부분이 603라인):

           if (item == null) {
                throw new NullArgumentException("item");
            }

            //중간 생략
            List<PortalMenu> children = getMenuItems(item.getPortal().getId(), item
                    .getId());

            for (PortalMenu child : children) {
                deleteMenuItem(child);
            }

신기하게도 아직까지 면접을 본 개발자 중에 이런 문제를 보고 곧바로 널포인터 예외의 원인을 짚어내는 지원자는 거의 없었습니다. 글을 읽으시는 분들은 모두 금방 답이 보이시나요?

많은 수의 지원자들이 'children'이나 'item.getId()' 등에 널값이 들어간 것 같다고 답했습니다. 이론적으로 해당 라인에서 널값이 들어갈 수 있는 모든 경우의 수는 (1) children (2) item (3) item.getPortal() (4) item.getPortal().getId() (5) item.getId() 이렇게 다섯 가지입니다.

이 중 적어도 두 가지, 즉 (2)번 혹은 (3)번으로 가능성을 바로 좁히지 못한다면 그것은 널포인터 예외의 의미를 정확하게 파악하지 못하고 있기 때문입니다. 널포인터 예외는 단순하게 변수에 널값이 들어가서 생기는 오류가 아닙니다. 널포인터 예외는 명확하게 객체의 널레퍼런스에 대해 메소드 호출이나 필드 참조 등의 작업을 했을 때 발생하는 문제라는 것을 이해한다면 이런 문제는 곧바로 원인을 좁힐 수 있어야 합니다.

즉, (1)번의 경우처럼 단순히 변수에 널값을 할당하는 것만으로는 절대로 널포인터 예외가 날 수 없습니다. 그리고 만일 (4) 번 item.getPortal().getId()이나 (5)번 item.getId()이 널이라면 이는 널 레퍼런스에 대한 호출이 아니라 널값을 getMenuItems라는 메소드의 인자로 넘기는 것 뿐이기 때문에 역시 널포인터 예외의 원인이 될 수 없습니다. 물론 getMenuItem 메소드 안에서 해당 인자에 대한 널체크 없이 값을 사용하다가 예외가 날 수도 있겠지만 이 경우엔 절대로 트레이스 상에 굵은 글자로 표시된 603라인에서 예외를 뿌리지 않습니다.

그렇다면 남은 가능성은 (2)번 item이 널이거나 (3)번 item.getPortal()이 널인 경우뿐인데, item 변수는 위에서 널체크를 하기 때문에 603라인에서 절대로 널값을 가질 수 없습니다. 그렇기 때문에 답은 (3)번이 되는 것입니다.

너무 문제가 어렵나요? 길게 설명했지만 개발을 하면 매우 흔하게 접할 수 있는 예외이며 따져보면 결코 어려운 내용이 아닙니다. 위와 같은 문제는 이미 스택트레이스를 능숙하게 읽을 수 있고 널포인터 예외를 이해하고 있는 개발자라면 몇 초 안에 곧바로 원인을 파악할 수 있는 문제입니다.

왜 개발을 공부 하면서 정확한 의미를 알아야 하는지, 스택트레이스 읽는 법과 같은 기초에 충실해야 되는 지는 이런 부분에서 나타나는 것입니다. 실제로 실무 현장에서 봐도 같은 상황이 주어졌을 때 어떤 개발자는 저런 복잡한 트레이스를 눈으로 한 번 쓱 훑어보고 바로 문제를 깨닫는 한편, 어떤 개발자는 왜 어제까지 되던게 안되는 걸까 온갖 상상의 나래를 펼치다가 무작위로 코드도 바꾸어 보고 System.out.println으로 로그도 아무데나 찍어보고 별의 별 의미없는 삽질을 하고서야 겨우 소 뒷걸음으로 쥐잡는 격으로 문제를 해결하기도 하는 것입니다.

[출처] [초보 개발자분들에게] 스택트레이스(stack trace)에 겁먹지 말자. (남궁성의 코드초보스터디(자바 java, c언어, javascript, python) |작성자 fender