Spring MyBatis에 log4jdbc-log4j2 설정하기

추가사항(20180819)

이 설정은 스프링 mybatis 환경에서 DAO Junit 테스트에 대해서만 로그가 발생한다. 기존의 log4j가 동작하지 않으며 java 소스의 logger 부분이 동작하지 않는다. 현재 log4j2의 환경설정에 문제가 있어 보인다. 찾는중 ....

들어가기

MyBatis를 사용해서 개발하다가 보면 가끔 잘못된 SQL이나 잘못된 속성의 이름으로 인해서 예외가 발생하는 경우가 종종 있다. 이런 경우를 대비해서 MyBatis의 로그를 보다 자세히 조사할 수 있도록 로그를 설정해 주는 것이 좋다.

Log4jdbc-log4j2라는 라이브러리를 이용하면, 기존의 jdbc datasource보다 더 상세한 로그를 콘솔에서 확인할수 있다. 다만 log4jdbc를 이용하는 경우 속도가 기존보다 저하될수 있고, 데이터베이스에 따라서 지원되지 않는 경우도 있으므로 설정 후에 정상적 동작을 반드시 확인해야 한다.


Spring MVC 프로젝트 + MySql8 + Mybatis 환경에 Log4jdbc-log4j2 적용실습

1.pom.xml에 log4jdbc-log4j2 라이브러리를 추가하자.

아래 내용을 pom.xml에 추가하자.

1
2
3
4
5
6
<!-- mybatis log4jdbc-log4j2 라이브러리 -->
<dependency>
<groupId>org.bgee.log4jdbc-log4j2</groupId>
<artifactId>log4jdbc-log4j2-jdbc4</artifactId>
<version>1.16</version>
</dependency>

2.root-context.xml파일에 dataSource를 수정하자.

root-context.xml파일의 dataSource 빈을 아래처럼 수정하자.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
<!-- 	기존 데이터 소스 설정
<bean id="dataSource" class="org.springframework.jdbc.datasource.DriverManagerDataSource">
<property name="driverClassName" value="com.mysql.cj.jdbc.Driver"></property>
<property name="url" value="jdbc:mysql://127.0.0.1:3306/mokaboard_dev?useSSL=false"></property>
<property name="username" value="mokaboard"></property>
<property name="password" value="password"></property>
</bean>
-->

<!-- 변경된 datasouce -->
<bean id="dataSource" class="org.springframework.jdbc.datasource.DriverManagerDataSource">
<property name="driverClassName" value="net.sf.log4jdbc.sql.jdbcapi.DriverSpy"></property>
<property name="url" value="jdbc:log4jdbc:mysql://127.0.0.1:3306/mokaboard_dev?useSSL=false"></property>
<property name="username" value="mokaboard"></property>
<property name="password" value="password"></property>
</bean>

3.log4jdbc.log4j2.properties파일과 logback.xml 파일을 추가하자.

src/main/resource 경로에 log4jdbc.log4j2.properties 파일을 생성하고 아래 내용을 입력하자.

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

src/main/resource 경로에 logback.xml 파일을 생성하고 아래 내용을 입력하자.

1
2
3
4
5
6
7
8
9
10
11
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml" />
<logger name="jdbc.splonly" level="DEBUG" />
<logger name="jdbc.sqltiming" level="INFO" />
<logger name="jdbc.audit" level="WARN" />
<logger name="jdbc.resultset" level="ERROR" />
<logger name="jdbc.resultsettable" level="ERROR" />
<logger name="jdbc.connection" level="INFO" />
</configuration>

log4jdbc.log4j2.properties파일과 logback.xml 위치

4.테스트 해보자

임의의 테이블을 생성하고, VO, DAO, DAOImpl, MybatisMapper.xml을 추가한뒤

/src/test/java 경로에 단순히 테이블에 Mybatis를 이용해 데이터를 insert하고 그 결과 로그를 확인해 보자.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
INFO : org.springframework.test.context.support.DefaultTestContextBootstrapper - Loaded default TestExecutionListener class names from location [META-INF/spring.factories]: [org.springframework.test.context.web.ServletTestExecutionListener, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener, org.springframework.test.context.support.DependencyInjectionTestExecutionListener, org.springframework.test.context.support.DirtiesContextTestExecutionListener, org.springframework.test.context.transaction.TransactionalTestExecutionListener, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener]
INFO : org.springframework.test.context.support.DefaultTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.web.ServletTestExecutionListener@402f32ff, org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@573f2bb1, org.springframework.test.context.support.DependencyInjectionTestExecutionListener@5ae9a829, org.springframework.test.context.support.DirtiesContextTestExecutionListener@6d8a00e3, org.springframework.test.context.transaction.TransactionalTestExecutionListener@548b7f67, org.springframework.test.context.jdbc.SqlScriptsTestExecutionListener@7ac7a4e4]
INFO : org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from file [C:\Users\amagr\Desktop\projectes\MokaBoard\src\main\webapp\WEB-INF\spring\root-context.xml]
INFO : org.springframework.context.support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@548e7350: startup date [Fri Jul 27 23:48:12 KST 2018]; root of context hierarchy
INFO : org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
INFO : org.springframework.jdbc.datasource.DriverManagerDataSource - Loaded JDBC driver: net.sf.log4jdbc.sql.jdbcapi.DriverSpy
Log4j 동작 테스트
INFO : jdbc.connection - 1. Connection opened
INFO : jdbc.audit - 1. Connection.new Connection returned
INFO : jdbc.audit - 1. Connection.getAutoCommit() returned true
INFO : jdbc.audit - 1. PreparedStatement.new PreparedStatement returned
INFO : jdbc.audit - 1. Connection.prepareStatement(select now()) returned net.sf.log4jdbc.sql.jdbcapi.PreparedStatementSpy@415b0b49
INFO : jdbc.sqlonly - select now()

INFO : jdbc.sqltiming - select now()
{executed in 22 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@383dc82c
INFO : jdbc.resultset - 1. ResultSet.getMetaData() returned com.mysql.cj.jdbc.result.ResultSetMetaData@5f9edf14 - Field level information:
com.mysql.cj.result.Field@68746f22[catalog=null,tableName=null,originalTableName=null,columnName=now(),originalColumnName=null,mysqlType=12(FIELD_TYPE_DATETIME),sqlType=93,flags= BINARY, charsetIndex=63, charsetName=ISO-8859-1]
INFO : jdbc.resultset - 1. ResultSet.getType() returned 1003
INFO : jdbc.resultset - 1. ResultSet.next() returned true
INFO : jdbc.resultset - 1. ResultSet.getString(now()) returned 2018-07-27 14:48:14
INFO : jdbc.resultset - 1. ResultSet.wasNull() returned false
INFO : jdbc.resultsettable -
|--------------------|
|now() |
|--------------------|
|2018-07-27 14:48:14 |
|--------------------|

INFO : jdbc.resultset - 1. ResultSet.next() returned false
INFO : jdbc.resultset - 1. ResultSet.close() returned void
INFO : jdbc.audit - 1. PreparedStatement.getConnection() returned net.sf.log4jdbc.sql.jdbcapi.ConnectionSpy@4c2bb6e0
INFO : jdbc.audit - 1. Connection.getMetaData() returned com.mysql.cj.jdbc.DatabaseMetaDataUsingInfoSchema@3e62d773
INFO : jdbc.audit - 1. PreparedStatement.getMoreResults() returned false
INFO : jdbc.audit - 1. PreparedStatement.getUpdateCount() returned -1
INFO : jdbc.audit - 1. PreparedStatement.close() returned
INFO : jdbc.connection - 1. Connection closed
INFO : jdbc.audit - 1. Connection.close() returned
DB 시간:2018-07-27 14:48:14
INFO : jdbc.connection - 2. Connection opened
INFO : jdbc.audit - 2. Connection.new Connection returned
INFO : jdbc.audit - 2. Connection.getAutoCommit() returned true
INFO : jdbc.audit - 2. PreparedStatement.new PreparedStatement returned
INFO : jdbc.audit - 2. Connection.prepareStatement(insert into tbl_member (userid, userpw, username, email)
values(?, ?, ?, ?)) returned net.sf.log4jdbc.sql.jdbcapi.PreparedStatementSpy@3cce57c7
INFO : jdbc.audit - 2. PreparedStatement.setString(1, "user10") returned
INFO : jdbc.audit - 2. PreparedStatement.setString(2, "user10") returned
INFO : jdbc.audit - 2. PreparedStatement.setString(3, "USER10") returned
INFO : jdbc.audit - 2. PreparedStatement.setString(4, "user10@aaa.com") returned
INFO : jdbc.sqlonly - insert into tbl_member (userid, userpw, username, email) values('user10', 'user10', 'USER10',
'user10@aaa.com')

INFO : jdbc.sqltiming - insert into tbl_member (userid, userpw, username, email) values('user10', 'user10', 'USER10',
'user10@aaa.com')
{executed in 21 msec}
INFO : jdbc.audit - 2. PreparedStatement.execute() returned false
INFO : jdbc.audit - 2. PreparedStatement.getUpdateCount() returned 1
INFO : jdbc.audit - 2. PreparedStatement.close() returned
INFO : jdbc.connection - 2. Connection closed
INFO : jdbc.audit - 2. Connection.close() returned
INFO : org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.GenericApplicationContext@548e7350: startup date [Fri Jul 27 23:48:12 KST 2018]; root of context hierarchy

기존보다 뭔가 자세하고? 상세히 로그가 찍히는 것을 확인 할수 있다.

이상, 끝!