[log4j2] DefaultResultSetCollector.methodReturned NullException

DefaultResultSetCollector.methodReturned NullException 에러발생

 

log4j2에서 아래의 GETTER에 담은 타입이 없으면 에러가 발생함

private static final List<String> GETTERS = Arrays.asList("getString", "getLong", "getInt", "getDate", "getTimestamp", "getTime", "getBigDecimal", "getFloat", "getDouble", "getByte", "getShort", "getObject", "getBoolean");

결론

• log4j2로 담을때 첫번째 뽑는 필드가 위에 없는 NULL 인 데이터가 있으면 에러가난다 (ex. CLOB)
• 첫번째 뽑아오는 필드를 위에 GETTERS에 선언된 타입의 필드로 뽑아오면 NullException 해결

> CLOB 타입은 안됨
> String 타입인 VARCHAR는 되지만, NVARCHAR는 안됨

 

아래 내용 출처: https://bbundoli.tistory.com/35

최근 업무 중 여태껏 한 번도 마주치지 못한 괴상한 버그, 음 버그라고 하는 게 맞을 지는 모르겠지만, 아무튼 좀 어이없는 녀석을 만나 기록해둔다.

목록 조회 쿼리 수행시 다음과 같은 에러 발생.

### Error querying database. Cause: java.lang.NullPointerException
### The error may exist in file [...매퍼 xml 파일 경로...]
### The error may involve ...매퍼 java interface 메서드 경로...
### The error occurred while handling results
### SQL: ...쿼리...
### Cause: java.lang.NullPointerException

개발자의 영원한 친구 NullPointerException! 별 거 아닌 놈인데 이 경우는 달랐다. 이게 발생할 이유가 도저히 없는 부분이었다. ResultSet 을 지정한 타입으로 매핑하는 도중 발생한 것인데, 이건 뭐 내가 직접한 것도 아니고 MyBatis 가 알아서 해주는 건데 거기서 이게 나올 일이 뭐가 있단 말인가?

 

일단은 콘솔에 찍힌 쿼리를 Heidi 에서 돌려보았다. 몇몇 컬럼 값이 null 인 행들이 있었다. 거의 본능적으로 그것들이 문제라는 것을 직감하고 해당 컬럼들을 IFNULL 로 감싸서 null 이면 빈문자열을 리턴하도록 쿼리를 변경했다. 일단은 그렇게 해서 Exception 은 해결되었다. 그런데 MyBatis 를 사용하면서 조회 목록 컬럼 값이 null 이어도 이런 일이 발생한 적은 한 번도 없었다. 상식적으로 생각해봐도 그런 일이 발생하면 안된다! 그런데 유독 그 쿼리에서만 이런 일이 발생했다. 왜일까...

 

예외 발생한 부분을 StackTrace 로 찍어보았다.

Caused by: java.lang.NullPointerException
	at net.sf.log4jdbc.sql.resultsetcollector.DefaultResultSetCollector.methodReturned(DefaultResultSetCollector.java:112)
	at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.reportAllReturns(ResultSetSpy.java:100)
	at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.reportReturn(ResultSetSpy.java:192)
	at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.wasNull(ResultSetSpy.java:2497)
	at org.apache.ibatis.type.BaseTypeHandler.getResult(BaseTypeHandler.java:70)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.applyAutomaticMappings(DefaultResultSetHandler.java:498)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getRowValue(DefaultResultSetHandler.java:385)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:339)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:314)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:287)
	at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:183)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)

MyBatis 가 아니라 log4jdbc 에서 발생한 것이었다. 아래서부터 소스를 따라가보니, MyBatis 가 쿼리를 날리고 받아온 ResultSet 을 매퍼에서 지정한 타입으로 매핑할 때 특정 컬럼 값이 null 이면 뭔가 문제가 발생한 것이다. 일단은 무엇이 null 인지 보려고 DefaultResultSetCollector 를 까보았다. IntelliJ 님은 java 소스가 없어도 class 파일을 참 깔끔하게 디컴파일 해주신다. 

public boolean methodReturned(ResultSetSpy resultSetSpy, String methodCall, Object returnValue, Object targetObject, Object... methodParams) {
    if (methodCall.startsWith("get") && methodParams != null && methodParams.length == 1) {
        String methodName = methodCall.substring(0, methodCall.indexOf(40));
        if (GETTERS.contains(methodName) && this.getColumnCount() != 0) {
            this.setColIndexFromGetXXXMethodParams(methodParams);
            this.makeRowIfNeeded();
            this.row.set(this.colIndex - 1, returnValue);
        }
    }

    if (methodCall.equals("wasNull()") && this.getColumnCount() != 0 && Boolean.TRUE.equals(returnValue)) {
        this.row.set(this.colIndex - 1, "[null]");
    }
    //중략...
}

흠, 두번째 if 문에서 this.row 가 null 이어서 set 할 때 NullPointerException 이 발생한다는 건데...인스턴스 변수로 선언된 이 놈의 타입은 java.util.List 였다. 그렇담 이걸 언제 생성해주지? 찾아보니까 바로 위의 if 문 this.makeRowIfNeeded() 메서드에서만 유일하게 this.row 를 생성해주고 있었다. 그러니까...첫번째 if 문과 그 안쪽의 if 문 두 개를 다 통과하지 못한 상태에서 두 번째 if 가 true 면 NullPointerException 이 발생할 수밖에 없단 얘기네. debug 모드로 확인하기 귀찮아서 그냥 맨 윗줄에 System.out.println 으로 파라미터 methodCall 를 찍어보았다. 그랬더니 이렇게 찍혔다.

 

new ResultSet
getMetaData()
getType()
next()
getClob(...컬럼명/Alias...)
wasNull()
getClob(...컬럼명/Alias...)
wasNull()
...이하 이런식...

 

그리고 GETTERS 는 이렇게 선언되어 있었다. getClob 이 없다! 그러니까 첫번째 컬럼부터 연속으로 Clob 타입 컬럼이 있는데 그러다가 그 중 값이 null 인 게 있으면 wasNull 로 null 여부 체크를 할 때 NullPointerException 이 발생하는 것이다!

private static final List<String> GETTERS = Arrays.asList("getString", "getLong", "getInt", "getDate", "getTimestamp", "getTime", "getBigDecimal", "getFloat", "getDouble", "getByte", "getShort", "getObject", "getBoolean");

 

이상한 건, 내가 조회한 테이블은 Clob컬럼이 없었는데 Clob 타입으로 인식된 컬럼이 있다는 것이었다. 그건...Subquery 였다. 여러가지로 더 테스트 해봤는데, Scala Subquery 가 모두 Clob 타입인 건 아니었다. 어떤 경우는 String 타입으로 찍혔다. 컬럼의 데이터 타입은 MyBatis 가 맘대로 하는 것이 아니라 ResultSet 의 MetaData 에 따라 정해진다. 근데 그건 DB 가 알려주는 건데...흠 MySQL 거 참 이상한 놈이네...같은 서브쿼리인데 어떨 때는 Clob 타입이고 또 어떨 때는 String 타입이고 이랬다 저랬다야...

 

DefaultResultSetCollector 는 jdbc.resultsettable logger 를 활성화할 때 사용되는 것 같다. 아래는 ResultSetSpy 소스 일부이다. 생성자에서 DefaultResultSetCollector 를 만드는 조건은 this.log.isResultSetCollectionEnabled() 가 true 일 때인데, 이게 jdbc.resultsettable logger 옵션인 거 같다.

 public ResultSetSpy(StatementSpy parent, ResultSet realResultSet, SpyLogDelegator logDelegator) {
    if (realResultSet == null) {
        throw new IllegalArgumentException("Must provide a non null real ResultSet");
    } else {
        this.realResultSet = realResultSet;
        this.parent = parent;
        this.log = logDelegator;
        if (this.log.isResultSetCollectionEnabled()) {
            this.resultSetCollector = new DefaultResultSetCollector(this.log.isResultSetCollectionEnabledWithUnreadValueFillIn());
        }
        this.reportReturn("new ResultSet", "", realResultSet);
    }
 }
    
protected void reportAllReturns(String methodCall, Object returnValue, Object... methodParams) {
    if (this.resultSetCollector != null) {
        boolean finished = this.resultSetCollector.methodReturned(this, methodCall, returnValue, this.realResultSet, methodParams);
        if (finished) {
            this.log.resultSetCollected(this.resultSetCollector);
            this.resultSetCollector.reset();
        }
    }
    String toString = "void";
    if (returnValue != null) {
        toString = returnValue.toString();
    }
    this.log.methodReturned(this, methodCall, toString);
}

jdbc.resultsettable 는 조회 결과 데이터를 표 모양으로 이쁘게 로깅하는 logger 옵션이다. ConsoleAppender 를 사용하면 개발할 때 따로 쿼리를 DB 툴에서 날려보지 않아도 콘솔에 조회 결과 데이터가 바로 찍히니 편할 때가 있다. 형상관리 서버에서 프로젝트 소스를 내려받을 때부터 ConsoleAppender 와 RollingFileAppender 둘 다 사용하도록 이 옵션이 활성화된 상태였는데, 목록 갯수가 많은 걸 조회할 때는 너무 버벅거려서 ConsoleAppender 설정을 지우고 사용하고 있었다. 아예 jdbc.resultsettable 옵션을 끄고 다시 테스트해보니까 NullPointerException 이 발생하지 않았다..

결론. 테스트 결과 아래와 같은 조건에서 이런 어이없는 NullPointerException 이 발생했다는 것을 확인했다.

log4jdbc 를 사용, 로깅 옵션을 활성화하고 jdbc.resultsettable 까지 설정하면 조회 결과 목록을 로그로 남기기 위해 DefaultResultSetCollector 가 사용된다.

이 때, MyBatis 를 이용하여 데이터 조회할 때 첫번째부터 데이터 타입이 Clob 으로 인식되는 컬럼들이 연속으로 이어지고 그 중에 값이 null 인 게 있으면, DefaultResultSetCollector 에서 NullPointerException 이 발생한다.

MySQL 셀렉트문 컬럼이 Scala Subquery 일때 간혹 Clob 타입으로 인식되는 경우가 있다.

그러면 이럴 때 해결 방법은...

log4jdbc 로깅 옵션에서 jdbc.resultsettable 를 끈다.
혹은, 데이터 타입이 DefaultResultSetCollector 의 GETTERS 목록에 포함된 컬럼을 셀렉트문 첫번째에 둔다.