Spring boot 3.0.0 기행기(2) - log4jdbc로 JPA Logging 하기 및 Formatter 적용

 살다보면 그런 일이 있습니다. 아무도 하지 않고 검색해도 안 나오는 걸 보니 누구도 시도하지 않았지만 혼자서 집요하게 집착하게 되는 그런 일. 오늘 한 짓은 그런 류의 짓거리 입니다.

 한창 JPA를 하기 위해 Entity도 이클립스로 자동 생성했으니 본격적으로 써 보기 위해 Spring boot Webflux로 코드 테이블에 있는 데이터들을 조회하는 API를 만들었습니다. 기본적으로 log4jdbc는 셋팅하고서 시작했기에 조회할 때 SQL이 콘솔 창에 그대로 찍히는 걸 볼 수 있었습니다. 그렇게 찍히는 건 좋은데 Mybatis는 일단 작성할 때 부터 보기 좋게 작성하기 때문에 상관 없었는데 아래 사진처럼 한줄로 쭉 찍히는 걸 볼 수 있었습니다.

 

한줄로 찍히는 극혐 쿼리

 이렇게 찍히면 콘솔에서 로그 찾을 때도 힘들고 해서 다른 방법을 찾아보기로 했습니다. 그렇게 구글의 바다를 조금 뒤져보니 Spring boot 설정 중에 

 

spring.jpa.properties.hibernate.format_sql=true

import java.io.IOException;
import java.io.LineNumberReader;
import java.io.StringReader;
import java.util.StringTokenizer;
import java.util.regex.Pattern;
 
 
import net.sf.log4jdbc.Properties;
import net.sf.log4jdbc.log.SpyLogDelegator;
import net.sf.log4jdbc.sql.Spy;
import net.sf.log4jdbc.sql.jdbcapi.ConnectionSpy;
import net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy;
import net.sf.log4jdbc.sql.resultsetcollector.ResultSetCollector;
import net.sf.log4jdbc.sql.resultsetcollector.ResultSetCollectorPrinter;
 
import org.slf4j.LoggerFactory;
import org.hibernate.engine.jdbc.internal.BasicFormatterImpl;
import org.slf4j.Logger;
 
/**
* Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
* <p>
* Modifications for log4j2: 
* <ul>
* <li>Modification of the signature of the method <code>connectionOpened(Spy)</code> into 
* <code>connectionOpened(Spy, long)</code>, to accept a parameter <code>execTime</code>, 
* defining the time elapsed to open the connection in ms. This new method simply delegates 
* to the formerly existing method, now private, so that the behavior of the slf4j logger is not modified. 
* See <code>SpyLogDelegator</code> for more details. 
* <li>Modification of the signature of the method <code>connectionClosed(Spy)</code> into 
* <code>connectionClosed(Spy, long)</code>, to accept a parameter <code>execTime</code>, 
* defining the time elapsed to open the connection in ms. This new method simply delegates 
* to the formerly existing method, now private, so that the behavior of the slf4j logger is not modified. 
* See <code>SpyLogDelegator</code> for more details. 
* </ul>
*
* @author Arthur Blake
* @author Frederic Bastian
* @author Mathieu Seppey
*/
public class Slf4jSpyLogDelegator implements SpyLogDelegator
{
   /**
    * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
    */
   public Slf4jSpyLogDelegator()
   {
   }
 
   // logs for sql and jdbc
 
   /**
    * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
    */
   private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");
 
   /**
    * Logger that shows JDBC calls for ResultSet operations
    */
   private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");
 
   /**
    * Logger that shows only the SQL that is occuring
    */
   private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");
 
   /**
    * Logger that shows the SQL timing, post execution
    */
   private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");
 
   /**
    * Logger that shows connection open and close events as well as current number
    * of open connections.
    */
   private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");
 
   // admin/setup logging for log4jdbc.
 
   /**
    * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
    */
   private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");
 
   /**
    * Logger that shows the forward scrolled result sets in a table
    */
   private final Logger resultSetTableLogger = LoggerFactory.getLogger("jdbc.resultsettable");  
 
   /**
    * Determine if any of the 5 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset |
    * jdbc.sqlonly | jdbc.sqltiming | jdbc.connection)
    *
    * @return true if any of the 5 spy jdbc/sql loggers are enabled at debug info or error level.
    */
   @Override
   public boolean isJdbcLoggingEnabled()
   {
       return jdbcLogger.isErrorEnabled() || resultSetLogger.isErrorEnabled() || sqlOnlyLogger.isErrorEnabled() ||
               sqlTimingLogger.isErrorEnabled() || connectionLogger.isErrorEnabled();
   }
 
 
   @Override
   public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime)
   {
       String classType = spy.getClassType();
       Integer spyNo = spy.getConnectionNumber();
       String header = spyNo + ". " + classType + "." + methodCall;
       if (sql == null)
       {
           jdbcLogger.error(header, e);
           sqlOnlyLogger.error(header, e);
           sqlTimingLogger.error(header, e);
       }
       else
       {
           sql = processSql(sql);
           jdbcLogger.error(header + " " + sql, e);
 
           // if at debug level, display debug info to error log
           if (sqlOnlyLogger.isDebugEnabled())
           {
               sqlOnlyLogger.error(getDebugInfo() + nl + spyNo + ". " + sql, e);
           }
           else
           {
               sqlOnlyLogger.error(header + " " + sql, e);
           }
 
           // if at debug level, display debug info to error log
           if (sqlTimingLogger.isDebugEnabled())
           {
               sqlTimingLogger.error(getDebugInfo() + nl + spyNo + ". " + sql + " {FAILED after " + execTime + " msec}", e);
           }
           else
           {
               sqlTimingLogger.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
           }
       }
   }
 
   @Override
   public void methodReturned(Spy spy, String methodCall, String returnMsg)
   {
       String classType = spy.getClassType();
       Logger logger=ResultSetSpy.classTypeDescription.equals(classType)?
               resultSetLogger:jdbcLogger;
       if (logger.isInfoEnabled())
       {
           String header = spy.getConnectionNumber() + ". " + classType + "." +
                   methodCall + " returned " + returnMsg;
           if (logger.isDebugEnabled())
           {
               logger.debug(header + " " + getDebugInfo());
           }
           else
           {
               logger.info(header);
           }
       }
   }    
 
   @Override
   public void constructorReturned(Spy spy, String constructionInfo)
   {
       // not used in this implementation -- yet
   }
 
   private static String nl = System.getProperty("line.separator");
 
   /**
    * Determine if the given sql should be logged or not
    * based on the various DumpSqlXXXXXX flags.
    *
    * @param sql SQL to test.
    * @return true if the SQL should be logged, false if not.
    */
   private boolean shouldSqlBeLogged(String sql)
   {
       if (sql == null)
       {
           return false;
       }
       sql = sql.trim();
 
       if (sql.length()<6)
       {
           return false;
       }
       sql = sql.substring(0,6).toLowerCase();
       return
               (Properties.isDumpSqlSelect() && "select".equals(sql)) ||
               (Properties.isDumpSqlInsert() && "insert".equals(sql)) ||
               (Properties.isDumpSqlUpdate() && "update".equals(sql)) ||
               (Properties.isDumpSqlDelete() && "delete".equals(sql)) ||
               (Properties.isDumpSqlCreate() && "create".equals(sql));
   }
 
   @Override
   public void sqlOccurred(Spy spy, String methodCall, String sql)
   {
       BasicFormatterImpl formatter = new BasicFormatterImpl();
       if (!Properties.isDumpSqlFilteringOn() || shouldSqlBeLogged(sql))
       {
           if (sqlOnlyLogger.isDebugEnabled())
           {    
               /**
                * 로그 찍을 때 jpa basic 포맷 적용
                */
               sqlOnlyLogger.debug(getDebugInfo() + nl + spy.getConnectionNumber() + ". " + formatter.format(processSql(sql)));
           }
           else if (sqlOnlyLogger.isInfoEnabled())
           {
               sqlOnlyLogger.info(processSql(sql));
           }
       }
   }
 
   /**
    * Break an SQL statement up into multiple lines in an attempt to make it
    * more readable
    *
    * @param sql SQL to break up.
    * @return SQL broken up into multiple lines
    */
   private String processSql(String sql)
   {
       if (sql==null)
       {
           return null;
       }
 
       if (Properties.isSqlTrim())
       {
           sql = sql.trim();
       }
 
       StringBuilder output = new StringBuilder();
 
       if (Properties.getDumpSqlMaxLineLength() <= 0)
       {
           output.append(sql);
       }
       else
       {
           // insert line breaks into sql to make it more readable
           StringTokenizer st = new StringTokenizer(sql);
           String token;
           int linelength = 0;
 
           while (st.hasMoreElements())
           {
               token = (String) st.nextElement();
 
               output.append(token);
               linelength += token.length();
               output.append(" ");
               linelength++;
               if (linelength > Properties.getDumpSqlMaxLineLength())
               {
                   output.append(nl);
                   linelength = 0;
               }
           }
       }
 
       if (Properties.isDumpSqlAddSemicolon())
       {
           output.append(";");
       }
 
       String stringOutput = output.toString();
 
       if (Properties.isTrimExtraBlankLinesInSql())
       {
           LineNumberReader lineReader = new LineNumberReader(new StringReader(stringOutput));
 
           output = new StringBuilder();
 
           int contiguousBlankLines = 0;
           try
           {
               while (true)
               {
                   String line = lineReader.readLine();
                   if (line==null)
                   {
                       break;
                   }
 
                   // is this line blank?
                   if (line.trim().length() == 0)
                   {
                       contiguousBlankLines ++;
                       // skip contiguous blank lines
                       if (contiguousBlankLines > 1)
                       {
                           continue;
                       }
                   }
                   else
                   {
                       contiguousBlankLines = 0;
                       output.append(line);
                   }
                   output.append(nl);
               }
           }
           catch (IOException e)
           {
               // since we are reading from a buffer, this isn't likely to happen,
               // but if it does we just ignore it and treat it like its the end of the stream
           }
           stringOutput = output.toString();
       }
 
       return stringOutput;
   }
 
   /**
    * Special call that is called only for JDBC method calls that contain SQL.
    *
    * @param spy        the Spy wrapping the class where the SQL occurred.
    *
    * @param execTime   how long it took the SQL to run, in milliseconds.
    *
    * @param methodCall a description of the name and call parameters of the
    *                   method that generated the SQL.
    *
    * @param sql        SQL that occurred.
    */
   @Override
   public void sqlTimingOccurred(Spy spy, long execTime, String methodCall, String sql)
   {
       if (sqlTimingLogger.isErrorEnabled() &&
               (!Properties.isDumpSqlFilteringOn() || shouldSqlBeLogged(sql)))
       {
           if (Properties.isSqlTimingErrorThresholdEnabled() &&
                   execTime >= Properties.getSqlTimingErrorThresholdMsec())
           {
               sqlTimingLogger.error(
                       buildSqlTimingDump(spy, execTime, methodCall, sql, sqlTimingLogger.isDebugEnabled()));
           }
           else if (sqlTimingLogger.isWarnEnabled())
           {
               if (Properties.isSqlTimingWarnThresholdEnabled() &&
                       execTime >= Properties.getSqlTimingWarnThresholdMsec())
               {
                   sqlTimingLogger.warn(
                           buildSqlTimingDump(spy, execTime, methodCall, sql, sqlTimingLogger.isDebugEnabled()));
               }
               else if (sqlTimingLogger.isDebugEnabled())
               {
                   sqlTimingLogger.debug(
                           buildSqlTimingDump(spy, execTime, methodCall, sql, true));
               }
               else if (sqlTimingLogger.isInfoEnabled())
               {
                   sqlTimingLogger.info(
                           buildSqlTimingDump(spy, execTime, methodCall, sql, false));
               }
           }
       }
   }
 
   /**
    * Helper method to quickly build a SQL timing dump output String for
    * logging.
    *
    * @param spy        the Spy wrapping the class where the SQL occurred.
    *
    * @param execTime   how long it took the SQL to run, in milliseconds.
    *
    * @param methodCall a description of the name and call parameters of the
    *                   method that generated the SQL.
    *
    * @param sql        SQL that occurred.
    *
    * @param debugInfo  if true, include debug info at the front of the output.
    *
    * @return a SQL timing dump String for logging.
    */
   private String buildSqlTimingDump(Spy spy, long execTime, String methodCall,
           String sql, boolean debugInfo)
   {
       StringBuffer out = new StringBuffer();
 
       if (debugInfo)
       {
           out.append(getDebugInfo());
           out.append(nl);
           out.append(spy.getConnectionNumber());
           out.append(". ");
       }
 
       // NOTE: if both sql dump and sql timing dump are on, the processSql
       // algorithm will run TWICE once at the beginning and once at the end
       // this is not very efficient but usually
       // only one or the other dump should be on and not both.
 
       sql = processSql(sql);
 
       out.append(sql);
       out.append(" {executed in ");
       out.append(execTime);
       out.append(" msec}");
 
       return out.toString();
   }
 
   /**
    * Get debugging info - the module and line number that called the logger
    * version that prints the stack trace information from the point just before
    * we got it (net.sf.log4jdbc)
    *
    * if the optional log4jdbc.debug.stack.prefix system property is defined then
    * the last call point from an application is shown in the debug
    * trace output, instead of the last direct caller into log4jdbc
    *
    * @return debugging info for whoever called into JDBC from within the application.
    */
   private static String getDebugInfo()
   {
       Throwable t = new Throwable();
       t.fillInStackTrace();
 
       StackTraceElement[] stackTrace = t.getStackTrace();
 
       if (stackTrace != null)
       {
           String className;
 
           StringBuffer dump = new StringBuffer();
 
           /**
            * The DumpFullDebugStackTrace option is useful in some situations when
            * we want to see the full stack trace in the debug info-  watch out
            * though as this will make the logs HUGE!
            */
           if (Properties.isDumpFullDebugStackTrace())
           {
               boolean first=true;
               for (int i = 0; i < stackTrace.length; i++)
               {
                   className = stackTrace[i].getClassName();
                   if (!className.startsWith("net.sf.log4jdbc"))
                   {
                       if (first)
                       {
                           first = false;
                       }
                       else
                       {
                           dump.append("  ");
                       }
                       dump.append("at ");
                       dump.append(stackTrace[i]);
                       dump.append(nl);
                   }
               }
           }
           else
           {
               dump.append(" ");
               int firstLog4jdbcCall = 0;
               int lastApplicationCall = 0;
 
               for (int i = 0; i < stackTrace.length; i++)
               {
                   className = stackTrace[i].getClassName();
                   if (className.startsWith("net.sf.log4jdbc"))
                   {
                       firstLog4jdbcCall = i;
                   }
                   else if (Properties.isTraceFromApplication() &&
                           Pattern.matches(Properties.getDebugStackPrefix(), className))
                   {
                       lastApplicationCall = i;
                       break;
                   }
               }
               int j = lastApplicationCall;
 
               if (j == 0)  // if app not found, then use whoever was the last guy that called a log4jdbc class.
               {
                   j = 1 + firstLog4jdbcCall;
               }
 
               dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").
               append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
           }
 
           return dump.toString();
       }
       return null;
   }
 
   @Override
   public void debug(String msg)
   {
       debugLogger.debug(msg);
   }
 
   @Override
   public void connectionOpened(Spy spy, long execTime)
   {
       //we just delegate to the already existing method, 
       //so that we do not change the behavior of the standard implementation
       this.connectionOpened(spy);
   }
 
   /**
    * Called whenever a new connection spy is created.
    *
    * @param spy ConnectionSpy that was created.
    */
   private void connectionOpened(Spy spy)
   {
       if (connectionLogger.isDebugEnabled())
       {          
           connectionLogger.info(spy.getConnectionNumber() + ". Connection opened " +
                   getDebugInfo());
           connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
       }
       else
       {
           connectionLogger.info(spy.getConnectionNumber() + ". Connection opened");
       }
   }
 
   @Override
   public void connectionClosed(Spy spy, long execTime)
   {
       //we just delegate to the already existing method, 
       //so that we do not change the behavior of the standard implementation
       this.connectionClosed(spy);
   }
 
   /**
    * Called whenever a connection spy is closed.
    *
    * @param spy ConnectionSpy that was closed.
    */
   private void connectionClosed(Spy spy)
   {
       if (connectionLogger.isDebugEnabled())
       {
           connectionLogger.info(spy.getConnectionNumber() + ". Connection closed " +
                   getDebugInfo());
           connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
       }
       else
       {
           connectionLogger.info(spy.getConnectionNumber() + ". Connection closed");
       }
   }
 
   @Override
   public void connectionAborted(Spy spy, long execTime)
   {
       this.connectionAborted(spy);
   }
 
   /**
    * Called whenever a connection spy is aborted.
    *
    * @param spy ConnectionSpy that was aborted.
    */
   private void connectionAborted(Spy spy)
   {
       if (connectionLogger.isDebugEnabled())
       {
           connectionLogger.info(spy.getConnectionNumber() + ". Connection aborted " +
                   getDebugInfo());
           connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
       }
       else
       {
           connectionLogger.info(spy.getConnectionNumber() + ". Connection aborted");
       }
   }
 
   @Override
   public boolean isResultSetCollectionEnabled() {
       return resultSetTableLogger.isInfoEnabled();
   }
 
   @Override
   public boolean isResultSetCollectionEnabledWithUnreadValueFillIn() {
       return resultSetTableLogger.isDebugEnabled();
   }
 
   @Override
   public void resultSetCollected(ResultSetCollector resultSetCollector) {
       String resultsToPrint = new ResultSetCollectorPrinter().getResultSetToPrint(resultSetCollector);    
       resultSetTableLogger.info(resultsToPrint);
   }
}
 
 

 위 소스가 Slf4jSpyLogDelegator을 꺼내서 바꿔준 소스입니다. 중간에 주석을 달아 놓았는데 로그 찍히는 곳에 JPA의 BasicFormatterImpl 을 적용해서 SQL을 이쁘게 찍어주게 했습니다. 이 소스를 복사해서 프로젝트 내에 아무곳에나 만들어준 후에 log4jdbc.log4j2.properties의 log4jdbc.spylogdelegator.name을 저 파일 경로로 변경해주면 

 

이제 흡족

 위와 같이 예쁘게 SQL이 찍히는 것을 볼 수 있습니다.