[스프링부트 (6)] Spring Boot 로그 설정(2) - DB로그(log4jdbc)

[스프링부트 (6)] Spring Boot 로그설정(2) - JDBC 로그 (log4jdbc)

 

이번 포스팅은 [ 스프링 부트  DB 로그 설정] 입니다. : ) 

 

 

 

 

0. logback

앞서 포스팅에서 logback설정을 해보았을 것이다.

다만 스프링 부트에서 logback은 기본으로 포함되어 있지만 jdbc에 대한 logback 설정은 되어 있지  않기 때문에 추가 설정이 필요하다.

이 부분에 대해서 간단하게 다음 포스팅과 같이 설정하면 하면되니 참고 하도록 하자.

 

 

1. JDBC 로그 설정

이번 포스팅에선 log4jdbc를 사용하려 쿼리를 예쁘게 찍어보려 한다.

쿼리문을 Console또는 로그 파일로 출력하고자 할때 다음과 같은 설정을 하면 된다.

 

▶ 1. 라이브러리 추가 (디펜던시  추가)

1) 메이븐 사용시 (pom.xml)

<!-- DB Logback -->
<dependency>
	<groupId>org.bgee.log4jdbc-log4j2</groupId>
	<artifactId>log4jdbc-log4j2-jdbc4.1</artifactId>
	<version>1.16</version>
</dependency>

 

2) 그래들 사용시 (build.gradle)

implementation 'org.bgee.log4jdbc-log4j2:log4jdbc-log4j2-jdbc4.1:1.16'

 

▶ 2. log4jdbc.log4j2.properties 파일 추가

 - resources 폴더 아래에 log4jdbc.log4j2.properties 파일을 추가하여 다음 2줄을 추가 하여 주자.

log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator
log4jdbc.dump.sql.maxlinelength=0

 

▶ 3. DB 설정정보 수정하기

 - 나의 경우에는 MariaDB를 사용하여 설정 하였다.

 - 기존 연결 설정은 주석 처리 하고 새로 Driver, Url 부분은 변경하여 준다.

#spring.datasource.driverClassName=org.mariadb.jdbc.Driver
#spring.datasource.url=jdbc:mariadb://localhost:3306/test?characterEncoding=UTF-8&serverTimezone=UTC
spring.datasource.driverClassName=net.sf.log4jdbc.sql.jdbcapi.DriverSpy
spring.datasource.url=jdbc:log4jdbc:mariadb://localhost:3306/test?characterEncoding=UTF-8&serverTimezone=UTC

 

1~3번 까지만 세팅해주면 DB 연결 정보에서부터 쿼리 까지 로그가 표현되는 것을 볼 수 있다.

다음이 그 로그 예시다.

INFO  20-02-16 15:12:53 [HikariDataSource:110] - HikariPool-1 - Starting...
INFO  20-02-16 15:12:53 [connection:541] - 1. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.getNetworkTimeout() returned 0
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [audit:175] - 1. Statement.new Statement returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.createStatement() returned net.sf.log4jdbc.sql.jdbcapi.StatementSpy@5397f52c
INFO  20-02-16 15:12:53 [sqlonly:228] - SELECT 1

INFO  20-02-16 15:12:53 [sqltiming:373] - SELECT 1
 {executed in 1 msec}
INFO  20-02-16 15:12:53 [audit:175] - 1. Statement.execute(SELECT 1) returned true
INFO  20-02-16 15:12:53 [audit:175] - 1. Statement.close() returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.getTransactionIsolation() returned 4
INFO  20-02-16 15:12:53 [HikariDataSource:123] - HikariPool-1 - Start completed.
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [audit:175] - 1. PreparedStatement.new PreparedStatement returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.prepareStatement(SELECT 'GOD' AS NAME) returned net.sf.log4jdbc.sql.jdbcapi.PreparedStatementSpy@580e0edc
INFO  20-02-16 15:12:53 [sqlonly:228] - SELECT 'GOD' AS NAME

INFO  20-02-16 15:12:53 [sqltiming:373] - SELECT 'GOD' AS NAME
 {executed in 2 msec}
INFO  20-02-16 15:12:53 [audit:175] - 1. PreparedStatement.execute() returned true
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.new ResultSet returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. PreparedStatement.getResultSet() returned net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy@2dea24e
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.getMetaData() returned org.mariadb.jdbc.MariaDbResultSetMetaData@700e7f9a
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.getType() returned 1003
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.isClosed() returned false
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.next() returned true
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.getString(NAME) returned GOD
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.isClosed() returned false
INFO  20-02-16 15:12:53 [resultsettable:610] - 
|-----|
|name |
|-----|
|GOD  |
|-----|

INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.next() returned false
INFO  20-02-16 15:12:53 [resultset:175] - 1. ResultSet.close() returned void
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.getMetaData() returned org.mariadb.jdbc.MariaDbDatabaseMetaData@34c5da85
INFO  20-02-16 15:12:53 [audit:175] - 1. PreparedStatement.close() returned 
INFO  20-02-16 15:12:53 [audit:175] - 1. Connection.clearWarnings() returned 
INFO  20-02-16 15:12:53 [connection:541] - 2. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 2. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 2. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 2. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 3. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 3. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 3. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 3. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 4. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 4. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 4. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 4. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 5. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 5. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 5. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 5. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 6. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 6. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 6. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 6. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 7. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 7. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 7. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 7. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 8. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 8. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 8. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 8. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 9. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 9. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 9. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 9. Connection.getAutoCommit() returned true
INFO  20-02-16 15:12:53 [connection:541] - 10. Connection opened
INFO  20-02-16 15:12:53 [audit:175] - 10. Connection.new Connection returned 
INFO  20-02-16 15:12:53 [audit:175] - 10. Connection.isReadOnly() returned false
INFO  20-02-16 15:12:53 [audit:175] - 10. Connection.getAutoCommit() returned true

 

 

쿼리 한줄 찍는데 너무 방대한 로그가 찍힌다고 생각된다.

위의 로그를 잘 살펴보면 connection, audit, resulttable, sqlonl 등을 눈여겨 살펴 보자.

log4jdbc는 SQL문에서부터 Connect정보, JDBC호출 정보, SQL 결과를 Table로 표현 하는 등의 옵션을 제공한다. 이에 대해 간단히 설명하고, 설정하는 방법을 살펴보자.

 

◎ jdbc.sqlonly

 - SQL문만을 로그로 남기며, PreparedStatement일 경우 관련된 argument 값으로 대체된 SQL문이 보여진다. 
◎ jdbc.sqltiming

 - SQL문과 해당 SQL을 실행시키는데 수행된 시간 정보(milliseconds)를 포함한다. 
◎ jdbc.audit

 - ResultSet을 제외한 모든 JDBC 호출 정보를 로그로 남긴다. 많은 양의 로그가 생성되므로 특별히 JDBC 문제를 추적해야 할 필요가 있는 경우를 제외하고는 사용을 권장하지 않는다. 
◎ jdbc.resultset

 - ResultSet을 포함한 모든 JDBC 호출 정보를 로그로 남기므로 매우 방대한 양의 로그가 생성된다. 
◎ jdbc.resultsettable

 - SQL 결과 조회된 데이터의 table을 로그로 남긴다.

 

 

앞서 포스팅을 통해서 logback-spring.xml 파일을 생성해 두었을 것이다. 해당 파일에 다음을 추가하면 된다.

나와 같은 경우는 sqltiming 옵션을 사용하려 한다. 쿼리 수행 시간과 쿼리문만 있으면 충분 할 것 같다.

<!-- log4jdbc 옵션 설정 -->
<logger name="jdbc" level="OFF"/>
<!-- 커넥션 open close 이벤트를 로그로 남긴다. -->
<logger name="jdbc.connection" level="OFF"/>
<!-- SQL문만을 로그로 남기며, PreparedStatement일 경우 관련된 argument 값으로 대체된 SQL문이 보여진다. -->
<logger name="jdbc.sqlonly" level="OFF"/>
<!-- SQL문과 해당 SQL을 실행시키는데 수행된 시간 정보(milliseconds)를 포함한다. -->
<logger name="jdbc.sqltiming" level="DEBUG"/>
<!-- ResultSet을 제외한 모든 JDBC 호출 정보를 로그로 남긴다. 많은 양의 로그가 생성되므로 특별히 JDBC 문제를 추적해야 할 필요가 있는 경우를 제외하고는 사용을 권장하지 않는다. -->
<logger name="jdbc.audit" level="OFF"/>
<!-- ResultSet을 포함한 모든 JDBC 호출 정보를 로그로 남기므로 매우 방대한 양의 로그가 생성된다. -->
<logger name="jdbc.resultset" level="OFF"/>
<!-- SQL 결과 조회된 데이터의 table을 로그로 남긴다. -->
<logger name="jdbc.resultsettable" level="OFF"/>

 

위와 같이 설정한 후 쿼리를 호출하여 보자.

DEBUG 20-02-16 21:31:57[http-nio-8080-exec-4] [sqltiming:368] -  com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:164)
1. SELECT 1
 {executed in 0 msec}
DEBUG 20-02-16 21:31:57[http-nio-8080-exec-4] [sqltiming:368] -  com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
1. SELECT 'GOD' AS NAME
 {executed in 1 msec}

약 80여줄의 로그 내용이 다음과 같이 간단하게 표현되는 것을 볼 수 있다.

 

이로써 간단하게 logback을 활용하여 log4jdbc 로깅 처리 하는 것 까지 완료 하였다.