WAS에서 동작하는 프로그램 원격 디버깅하기

[kiki]

0. 지혜롭게 살자
많은 개발자가 전통적(?)인 방법인 System.out....로 디버깅을 많이 하고 있다. 물론 이것처럼 확실한 방법도 없지만 eclipse나 다른 IDE의 디버그 기능을 이용하면 훨씬 빨리 문제를 찾을 수 있다.
특히 WAS에 배포된 환경에서 이런 방법으로 하려면 확인하기 위한 System.out...을 고칠 때마다 배포해야 하는데 이건 너무 고통스러운 작업이다.

단위 테스트시 에러가 발생했을 때는 eclipse등을 이용해서 디버깅하기가 수월하다.
그러나 WAS에 배포된 후에 에러가 발생했을 때는 약간의 작업이 필요하다. WAS를 eclipse에 embeded한 플러그인을 이용하는 방법도 있지만 WAS와 이클립스를 따로 띄워 원격으로 버그를 찾는 방법을 정리한다.
이럴 경우 서버환경에서 돌아가는 자바 코드의 문제점도 쉽게 잡을 수 있다. (물론 절대! 운영서버에서 하면 안되겠지만)

여기서는 tomcat 6와 eclipse 3.3 그리고 java6 환경을 가정하고 설명한다. (그 하위 버전도 방법은 동일하다)

1. 문제지점 찾기
WAS에서 애플리케이션을 배포하고 돌려보니 에러가 발생하고 아래와 같은 예외스택을 출력했다.

java.lang.NullPointerException
  kr.nextree.common.nexuser.spi.jdbc.JDBCCredentialsSPI.authenticate(JDBCCredentialsSPI.java:32)
  kr.nextree.common.nexuser.impl.NexUserImpl.authenticate(NexUserImpl.java:13)
  kr.nextree.bcf.user.impl.UserServiceImpl.authenticate(UserServiceImpl.java:79)
  kr.nextree.bcf.ui.authentication.BcfAuthenticationProvider.authenticate(BcfAuthenticationProvider.java:26)
  org.acegisecurity.providers.ProviderManager.doAuthentication(ProviderManager.java:195)
  org.acegisecurity.AbstractAuthenticationManager.authenticate(AbstractAuthenticationManager.java:43)
  ...

이걸보면 JDBCCredentialsSPI.java 소스의 32 라인에서 null 객체를 참조하여 뭔가를 했다는 것을 짐작할 수 있다. 그럼 그 소스를 볼까?

   conn = JDBCSPIEnv.getInstance().getDataSource().getConnection();
   ps = conn.prepareStatement(JDBCSPIEnv.getInstance().getAuthenticateSql());
   ps.setString(1, id);

   rs = ps.executeQuery();

   if (rs.next()) {
    return rs.getString(1).equals(NexUserEnv.getInstance().getPasswordEncoder().encode(password));
   }

아~ 한 줄에 많은 것들이 있네 ㅠㅠ. 이중 어떤 객체가 null 인지 알 수가 있나. 좀 고생하겠는데...

2. 디버깅을 걸자 (가장 중요)
다음과 같은 JVM 옵션을 사용하면 JVM을 기동할 때 디버그 모드로 기동되고 원격에서 그 디버그 세션으로 접속할 수 있다.

-Xdebug -Xnoagent -Xrunjdwp:transport=dt_socket,address=8000,server=y,suspend=n

이는 8000 소켓으로 디버그 세션을 열어두겠다는 뜻이다.

내 경우 Tomcat을 사용하기에 다음과 같이 JAVA_OPTS의 환경변수에 저 옵션을 설정했다. Tomcat은 JAVA_OPTS 환경변수를 이용하여 JVM을 기동한다.

>set JAVA_OPTS=-Xdebug -Xnoagent -Xrunjdwp:transport=dt_socket,address=8000,server=y,suspend=n

>catalina.bat run

시작쯤에 다음과 같은 라인이 출력되면서 기동되면 성공한 것이다.

...
Using JRE_HOME:        C:\java\jdk1.6.0_01
Listening for transport dt_socket at address: 8000
...

각 WAS에 -Xdebug ... 옵션을 설정하는 것은 조금씩 다르다. 각 WAS의 shell 스크립트를 살펴보고 적당한 환경변수를 주거나 직접 java 실행하는 부분에서 저 옵션을 추가하면 된다.
참고로 Maven 2로 개발할 경우 mvn jetty:run으로 WAS를 띄울 경우가 있는데 이런 경우는 다음과 같은 환경변수를 설정하고 띄우면 된다.

set MAVEN_OPTS= -Xdebug -Xnoagent -Xrunjdwp:transport=dt_socket,address=8000,server=y,suspend=n

3. JVM 디버깅 세션에 연결
이클립스에서 디버깅 세션을 열기 위해서는 다음 단계를 따라하면 된다. 물론 디버깅하기 위한 소스는 이클립스 프로젝트에 있다고 가정한다. 프로젝트를 선택한 상태에서 디버그를 시작하는 것을 있지 말라.

"Run > Open Debug Dialog..." 메뉴를 선택하면 아래와 같은 Debug 다이얼로그가 나타난다.

여기서 "Remote Java Application"을 선택하고 마우스 오른쪽 버튼을 클릭해 팝업 메뉴에서 "New"를 선택하면

위와 같이 새로운 디버그 연결을 위한 설정이 나타난다. 여기서 위와 같이 선택하고(Host와 Port는 변경할 수 있다. 위의 예에서 Port를 8000으로 설정했다.) "Debug 버튼"를 클릭한다.
그 후 "Debug" Perspective로 가면 (Window > Open Perspective를 통해 이동할 수 있음) 아래 그림과 같은 WAS의 쓰레드가 보이면 연결에 성공한 것이다.

3. Breakpoint 설정하기
이전 에러 스택을 통해 JDBCCredentialsSPI.java 소스의 32라인에서 무언가 null이라고 했다. 이 자바 소스를 열고 편집창 맨 앞에서 더블 클릭을 하거나 팝업 메뉴로 해당 라인에 breakpoint를 걸어두자.

4. 실행하고 상태 살펴보기(Inspect)
이제 에러가 난 부분을 실행하면 breakpoint에서 실행이 멈추고 대기할 것이다. 그럼 이제 어떤 부분이 null인지 살펴보자. Debug perspective에서 Variable 뷰에서 보면 rs는 nul로 나오지 않았다. 따라서 rs.getString(1) 부분이 null인지 살펴볼 것이다. 아래와 같이 rs.getString(1)을 선택하고 팝업메뉴로 "Inspect"를 선택한다.

그러면 위와 같이 현재의 rs.getStrng(1)을 평가하고 그 값을 보여준다. 이런 벌써 이 부분이 null인 것이 판명이 났다. 도대체 어떤 SQL을 실행했는데 첫번째 컬럼마저 null일까.

위의 소스에서 SQL 문장을 보려고 했다. 아 이것도 상수가 아니구나. 마찬가지 방법으로 inspect해서 SQL 문장을 확인한다. 소스 윗줄의 JDBCSPIEnv.getInstance().getAuthenticateSql()를 선택하여 살펴보았다. (팝업메뉴나 ctl+shift+i)

확인한 결과 실행한 SQL은 "select password from users where user_id = ?" 이고 넘어가는 파라메터는 "dykim"이었다.
DB의 테이블 내용을 살펴보니 dykim의 password 컬럼 값이 null 이었다.

아... rs.getString()이 null을 던질 수도 있는데... 단위 테스트하나 더 추가하고 고쳐야겠다.