본문으로 바로가기
반응형

[스프링부트 (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 로깅 처리 하는 것 까지 완료 하였다.

 

 

 

반응형

댓글을 달아 주세요

  1. 개발자J 2020.09.01 01:55

    안녕하세요. logback의 jdbc 관련 로그 레벨이 적용되지 않고
    최상위인 root 레벨만을 바라보는데 혹시 이유를 알고 계실까요?

    • BlogIcon windoksc 2020.10.02 15:45

      안녕하세요.
      저도 같은 문제에 부딪혀서 구글링 한 결과,
      <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
      <Marker>LOG4JDBC_NON_STATEMENT</Marker>
      <OnMatch>DENY</OnMatch>
      <OnMismatch>NEUTRAL</OnMismatch>
      </turboFilter>
      를 logback-spring.xml파일에 loggeroption설정 대신 적용 시키면 되더군요. 적용 지점은 property 아래입니다.
      참조 문서는 https://log4jdbc.brunorozendo.com/
      과 https://stackoverflow.com/questions/37086369/log4j2-markers-in-logback 입니다.

    • 대신 답변 해주신분이 계시네요~! 정말 감사합니다~!

  2. 정말강한호랑이 2021.05.25 14:10

    먼저 감사 인사부터 드리겠습니다.

    포스팅 하신 글 덕분에 엄청난 도움을 얻고 있습니다.

    혹시 해당 블로그의 스프링부트 프로젝트 포스트들을 차근차근 하면서

    대희님 블로그로 출처를 남기고 제 Github에 올려도될까요?

  3. 네~! 그렇게 해주시면 좋겠네요! 오늘도 즐거운 하루 되세요~!

  4. 개발자힘내자 2021.06.25 17:58

    안녕하세요.
    <logger name="jdbc.audit" level="OFF" appender-ref="console-infolog" />
    이렇게 해도
    [onnection adder] jdbc.audit : 10. Connection.getAutoCommit() returned true 계속 찍혀 나옵니다..
    해결방법이 없을까요 ㅠㅠ