MyBatis와 스프링 연동 4-3

▶log4jdbc-log4j2설정

 MyBatis는 내부적으로 JDBC의 PreparedStatement를 잉요해서 SQL을 처리함.따라서 SQL에 전달되는 파라미터는 JDBC에서 와 같이 '?'로 치환되어서 처리됨.

복잡한 SQL의 경우 '?'로 나오는 값이 제대로 되었는지 확인하기가 쉽지 않고 실행된 SQL의 내용을 정확히 확인하기는 어렵다. 이런 문제를 해결하기 위해서 

SQL을 변환해서 PreparedStatement에 사용된 '?'가 어떤 값으로 처리되었는지 확인하는 기능을 추가하도록함.

SQL 로그를 제대로 보기 위해 log4jdbc-log4j2 라이브러리를 사용함.

pom.xml 추가  

<!-- https://mvnrepository.com/artifact/org.bgee.log4jdbc-log4j2/log4jdbc-log4j2-jdbc4.1 -->
        <dependency>
            <groupId>org.bgee.log4jdbc-log4j2</groupId>
            <artifactId>log4jdbc-log4j2-jdbc4.1</artifactId>
            <version>1.16</version>
        </dependency>

추가한 후  1)로그 설정 파일을 추가하는 작업과 2)JDBC의 연결 정보를 수정해야함.

우선 src/main/resources밑에 log4jdbc-log4j2.preparties파일 추가함.

log4jdbc.log4j2.properties파일

log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator

log4jdbc를 이용하는 경우는 JDBC드라이버와 URL 정보를 수정해야함.

root-context.xml 일부 수정

    <!-- Root Context: defines shared resources visible to all other web components -->
        
        <bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
        <!-- <property name="driverClassName" value="oracle.jdbc.driver.OracleDriver"></property>
        <property name="jdbcUrl" value="jdbc:oracle:thin:@localhost:1521:orcl"></property> -->
        <property name="driverClassName"
        value="net.sf.log4jdbc.sql.jdbcapi.DriverSpy"></property>
        <property name="jdbcUrl"
        value="jdbc:log4jdbc:oracle:thin:@localhost:1521:orcl"></property>
        <property name="username" value="TEST_EX"></property>
        <property name="password" value="1234"></property>
        
        </bean>

dataSource() 에서  변경되는 부분은 JDBC 드라이버의 클래스를  net.sf.log4jdbc.sql.jdbccapi.DriverSpy로 수정하는 작업과 JDBC연결 URL부분에서 중간에 

log4jdbc문자열이 추가되는 부분임. 이 두 설정이 제대로 되어있지 않으면 데이터베이스의 로그가 정상적으로 기록이 안됨. 

설정 변경 후 테스트코드를 실행해 보면이전과 달리 JDBC와 관련된 로그들이 출력되는 것을 볼 수 있다 

INFO : jdbc.sqltiming - SELECT sysdate FROM dual 
 {executed in 1 msec}
INFO : jdbc.audit - 1. PreparedStatement.execute() returned true
INFO : jdbc.resultset - 1. ResultSet.new ResultSet returned 
INFO : jdbc.audit - 1. PreparedStatement.getResultSet() returned net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy@5b43fbf6
INFO : jdbc.resultset - 1. ResultSet.getMetaData() returned oracle.jdbc.driver.OracleResultSetMetaData@1080b026
INFO : jdbc.resultset - 1. ResultSet.getType() returned 1003
INFO : jdbc.resultset - 1. ResultSet.next() returned true
INFO : jdbc.resultset - 1. ResultSet.getString(SYSDATE) returned 2018-12-15 11:17:46
INFO : jdbc.resultset - 1. ResultSet.wasNull() returned false
INFO : jdbc.resultsettable - 
|--------------------|
|sysdate             |
|--------------------|
|2018-12-15 11:17:46 |
|--------------------|
 
INFO : jdbc.resultset - 1. ResultSet.next() returned false
INFO : jdbc.resultset - 1. ResultSet.close() returned void
INFO : jdbc.audit - 1. Connection.getMetaData() returned oracle.jdbc.driver.OracleDatabaseMetaData@27305e6
INFO : jdbc.audit - 1. PreparedStatement.isClosed() returned false
INFO : jdbc.audit - 1. PreparedStatement.close() returned 
INFO : jdbc.audit - 1. Connection.clearWarnings() returned 
INFO : org.zeorck.persistence.TimeMapperTests - 2018-12-15 11:17:46
INFO : org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.

JAVA설정 방법

RootConfig클래스 아래와 같이 반영

public class RootConfig {
    
    @Bean
    public DataSource dataSource() {
        HikariConfig hikariConfig=new HikariConfig();
        /*hikariConfig.setDriverClassName("oracle.jdbc.driver.OracleDriver");
        hikariConfig.setJdbcUrl("jdbc:oracle:thin:@localhost:1521:orcl");*/
        hikariConfig.setDriverClassName("net.sf.log4jdbc.sql.jdbcapi.DriverSpy");
        hikariConfig.setJdbcUrl("jdbc:log4jdbc:oracle:thin:@localhost:1521:orcl");
        hikariConfig.setUsername("TEST_EX");
        hikariConfig.setPassword("1234");
        
        HikariDataSource dataSource =new HikariDataSource(hikariConfig);
        
        return dataSource;
        
    }

▶로그의 레벨 설정

테스트를 실행하면 상당히 많은 양의 로그가 출력되기 때문에 불편하다.이런 상황에서는 로그 레벨을 이용해서 조금 수정해줄 필요가 있음.

테스트 코드가 실행될 때의 로그와 관련 설정은 src/test/resources밑에 log4j.xml을 이용함.(src/main/resources 아닌src/test/resources 란 걸 주의)

테스트코드가 실행될때 'INFO...',메세지는 log4j.xml의 마지막 부분에 있는 설정에 영향을 받기 때문

src/test/resources/log4j.xml 의 마지막 부분

<!-- Root Logger -->
    <root>
        <priority value="info" />
        <appender-ref ref="console" />
    </root>
    
</log4j:configuration>
 

만일 log4jdbc에서 출력되는 로그를 조절하고 싶다면 추가적인 <logger>를 지정해서 처리함.

<!-- 3rdparty Loggers -->
    <!-- <logger name="org.springframework.core"> <level value="info" /> </logger> 
        <logger name="org.springframework.beans"> <level value="info" /> </logger> 
        <logger name="org.springframework.context"> <level value="info" /> </logger> 
        <logger name="org.springframework.web"> <level value="info" /> </logger> -->
 
    <logger name="jdbc.audit">
        <level value="warn" />
    </logger>
    <logger name="jdbc.resulteset">
        <level value="warn" />
    </logger>
    <logger name="jdbc.connection">
        <level value="warn" />
    </logger>

기본 설정의 로그는 info 레벨이기 때문에 warn과 같이 좀더 높은 레벨의 로그만 기록하게 수정하면 테스트 코드를 실행할 때 이전에 비해 로그양이

줄어드는것을 볼 수 있음.(더 자세한내용 참고https://logging.apache.org/log4j/2.x/manual/customloglevels.html)

INFO : jdbc.resultset - 1. ResultSet.getString(SYSDATE) returned 2018-12-15 11:46:24
INFO : jdbc.resultset - 1. ResultSet.wasNull() returned false
INFO : jdbc.resultsettable - 
|--------------------|
|sysdate             |
|--------------------|
|2018-12-15 11:46:24 |
|--------------------|
 
INFO : jdbc.resultset - 1. ResultSet.next() returned false
INFO : jdbc.resultset - 1. ResultSet.close() returned void
INFO : org.zeorck.persistence.TimeMapperTests - 2018-12-15 11:46:24
INFO : org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.
GenericApplicationContext@18eed359: startup date [Sat Dec 15 11:46:22 KST 2018]; root of context hierarchy
INFO : com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
INFO : com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.

여기 까지 하신분은 스프링의 반을 끝냈다고 생각하셔도 좋습니다. 왜냐 하면 스프링은 설정이 반이기 때문에 ......