net.disy.oss.log4jdbc.log.log4j2.Log4j2SpyLogDelegator Maven / Gradle / Ivy

Go to download
package net.disy.oss.log4jdbc.log.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.MarkerManager;

import net.disy.oss.log4jdbc.Properties;
import net.disy.oss.log4jdbc.log.SpyLogDelegator;
import net.disy.oss.log4jdbc.log.log4j2.message.ConnectionMessage;
import net.disy.oss.log4jdbc.log.log4j2.message.ConnectionMessage.Operation;
import net.disy.oss.log4jdbc.log.log4j2.message.ExceptionOccuredMessage;
import net.disy.oss.log4jdbc.log.log4j2.message.MethodReturnedMessage;
import net.disy.oss.log4jdbc.log.log4j2.message.SqlTimingOccurredMessage;
import net.disy.oss.log4jdbc.sql.Spy;
import net.disy.oss.log4jdbc.sql.jdbcapi.ResultSetSpy;
import net.disy.oss.log4jdbc.sql.resultsetcollector.ResultSetCollector;
import net.disy.oss.log4jdbc.sql.resultsetcollector.ResultSetCollectorPrinter;

/**
 * Delegates JDBC spy logging events to log4j2.
 * 
 * Differences in implementation and behavior as compared to Slf4jSpyLogDelegator:
 * 

 * Only 2 loggers are used, instead of 6 in the Slf4jSpyLogDelegator:
 * one for logging all spy logging events
 * ("log4jdbc.log4j2", see LOGGER attribute),
 * another one for logging debugging within log4jdbc itself
 * ("log4jdbc.debug" logger, see DEBUGLOGGER attribute,
 * or Slf4jSpyLogDelegator debugLogger attribute).
 * 
The behavior of the loggers "jdbc.connection", "jdbc.resultset", and "jdbc.audit"
 * is reproduced through the use of Markers
 * within one single logger:
 * 
 * The Marker CONNECTION_MARKER, named "LOG4JDBC_CONNECTION"
 * 
The Marker RESULTSET_MARKER, named "LOG4JDBC_RESULTSET",
 * a child of the Marker JDBC_MARKER, named "LOG4JDBC_JDBC"
 * 
The Marker RESULTSETTABLE_MARKER, named "LOG4JDBC_RESULTSETTABLE",
 * a child of the Marker RESULTSET_MARKER, named "LOG4JDBC_RESULTSET"
 * 
The Marker AUDIT_MARKER, named "LOG4JDBC_AUDIT",
 * a child of the Marker JDBC_MARKER, named "LOG4JDBC_JDBC"
 * 
JDBC_MARKER and CONNECTION_MARKER are children of
 * NON_STATEMENT_MARKER, named "LOG4JDBC_NON_STATEMENT".
 * This is to easily reproduce standard log4jdbc loggers behavior,
 * and behavior of log4jdbc-remix.
 * 
 * 
The behavior of the logger "jdbc.sqlonly"
 * (see for instance Slf4jSpyLogDelegator sqlOnlyLogger attribute)
 * is not reproduced.
 * This is for the will of keeping one single logger, while the logging of spy events
 * immediately, before the action is executed and before knowing the execution time,
 * would definitely require another logger.
 * Also, execution time seems to be an always-useful information to get.
 * 
As a consequence, the method sqlOccured(Spy, String, String) is not implemented.
 * 
Thanks to the use of Markers, some options configured
 * in the log4jdbc properties file can be set directly in the log4j2 configuration file:
 * 
 * log4jdbc.dump.sql.select property can be set using the Marker SELECT_MARKER,
 * named "LOG4JDBC_SELECT"
 * 
log4jdbc.dump.sql.insert property can be set using the Marker INSERT_MARKER,
 * named "LOG4JDBC_INSERT"
 * 
log4jdbc.dump.sql.update property can be set using the Marker UPDATE_MARKER,
 * named "LOG4JDBC_UPDATE"
 * 
log4jdbc.dump.sql.delete property can be set using the Marker DELETE_MARKER,
 * named "LOG4JDBC_DELETE"
 * 
log4jdbc.dump.sql.create property can be set using the Marker CREATE_MARKER,
 * named "LOG4JDBC_CREATE"
 * 
 * These Markers are all children of the Marker SQL_MARKER, named "LOG4JDBC_SQL".
 * These properties can also be set through the log4jdbc properties file.
 * They would have priority over the Markers.
 * 
The interface SpyLogDelegator,
 * and the classes Slf4jSpyLogDelegator, DriverSpy,
 * ConnectionSpy, SpyLogFactory,
 * StatementSpy and PreparedStatementSpy
 * have been modified. See their corresponding javadoc for information about the changes.
 * 
 *
 * @author Frederic Bastian
 * @author Mathieu Seppey
 * @see #LOGGER
 * @see #DEBUGLOGGER
 * @see net.disy.oss.log4jdbc.log.slf4j.Slf4jSpyLogDelegator
 * @see SpyLogDelegator
 * @see net.disy.oss.log4jdbc.sql.jdbcapi.DriverSpy
 * @see net.disy.oss.log4jdbc.log.SpyLogFactory
 */
public class Log4j2SpyLogDelegator implements SpyLogDelegator {
  /**
   * Logger responsible of logging all spy events
   */
  private static final Logger LOGGER = LogManager.getLogger("log4jdbc.log4j2");
  /**
   * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
   * @see Log4j2SpyLogDelegator#debug
   */
  private static final Logger DEBUGLOGGER = LogManager.getLogger("log4jdbc.debug");

  /**
   * Marker to log events generated by Statements
   * (corresponds to the "jdbc.sqltiming" logger in the standard implementation)
   */
  private static final Marker SQL_MARKER = MarkerManager.getMarker("LOG4JDBC_SQL");
  /**
   * Marker to log events following select statements
   * (corresponds to the log4jdbc.dump.sql.select property)
   */
  private static final Marker SELECT_MARKER = MarkerManager.getMarker("LOG4JDBC_SELECT", SQL_MARKER);
  /**
   * Marker to log events following insert statements
   * (corresponds to the log4jdbc.dump.sql.insert property)
   */
  private static final Marker INSERT_MARKER = MarkerManager.getMarker("LOG4JDBC_INSERT", SQL_MARKER);
  /**
   * Marker to log events following update statements
   * (corresponds to the log4jdbc.dump.sql.update property)
   */
  private static final Marker UPDATE_MARKER = MarkerManager.getMarker("LOG4JDBC_UPDATE", SQL_MARKER);
  /**
   * Marker to log events following delete statements
   * (corresponds to the log4jdbc.dump.sql.delete property)
   */
  private static final Marker DELETE_MARKER = MarkerManager.getMarker("LOG4JDBC_DELETE", SQL_MARKER);
  /**
   * Marker to log events following create statements
   * (corresponds to the log4jdbc.dump.sql.create property)
   */
  private static final Marker CREATE_MARKER = MarkerManager.getMarker("LOG4JDBC_CREATE", SQL_MARKER);
  /**
   * Marker parent of the CONNECTION_MARKER and
   * JDBC_MARKER, to easily disable logging of connection, JDBC, and ResultSet calls.
   * This is to easily reproduce log4jdbc standard loggers behaviors.
   */
  private static final Marker NON_STATEMENT_MARKER = MarkerManager.getMarker("LOG4JDBC_NON_STATEMENT");
  /**
   * Marker to log connections events
   * (corresponds to the "jdbc.connection" logger in the standard implementation)
   */
  private static final Marker CONNECTION_MARKER = MarkerManager.getMarker("LOG4JDBC_CONNECTION", NON_STATEMENT_MARKER);
  /**
   * Marker to log all JDBC calls including ResultSets,
   * and result sets as tables.
   */
  private static final Marker OTHER_MARKER = MarkerManager.getMarker("LOG4JDBC_OTHER", NON_STATEMENT_MARKER);
  /**
   * Marker to log all JDBC calls including ResultSets
   */
  private static final Marker JDBC_MARKER = MarkerManager.getMarker("LOG4JDBC_JDBC", OTHER_MARKER);
  /**
   * Marker to log all JDBC calls except for ResultSets
   * (corresponds to the "jdbc.audit" logger in the standard implementation)
   */
  private static final Marker AUDIT_MARKER = MarkerManager.getMarker("LOG4JDBC_AUDIT", JDBC_MARKER);
  /**
   * Marker to log ResultSets calls
   * (corresponds to the "jdbc.resultset" logger in the standard implementation)
   */
  private static final Marker RESULTSET_MARKER = MarkerManager.getMarker("LOG4JDBC_RESULTSET", JDBC_MARKER);
  /**
   * Marker to log JDBC ResultSets as table.
   * Functionality inherited from log4jdbc-remix.
   * (corresponds to the "jdbc.resultsettable" logger in the log4jdbc-remix implementation)
   * @see net.disy.oss.log4jdbc.sql.resultsetcollector
   */
  private static final Marker RESULTSETTABLE_MARKER =
      MarkerManager.getMarker("LOG4JDBC_RESULTSETTABLE", OTHER_MARKER);
  /**
   * Marker to log Exceptions.
   * These are not specific to one logger in the standard implementation,
   * and they are not logged by the loggers "jdbc.resultset" and "jdbc.connection"
   * (bug, or a hope for no exception to occur for these events?)
   */
  private static final Marker EXCEPTION_MARKER = MarkerManager.getMarker("LOG4JDBC_EXCEPTION");

  @Override
  public boolean isJdbcLoggingEnabled() {
    return LOGGER.isErrorEnabled();
  }

  @Override
  public void exceptionOccured(
      Spy spy, String methodCall, Exception e,
      String sql, long execTime) {

    LOGGER.error(EXCEPTION_MARKER, new ExceptionOccuredMessage(spy, methodCall,
        sql, execTime, LOGGER.isDebugEnabled(EXCEPTION_MARKER)), e);
  }

  @Override
  public void methodReturned(Spy spy, String methodCall, String returnMsg) {
    String classType = spy.getClassType();
    Marker marker = ResultSetSpy.classTypeDescription.equals(classType) ?
        RESULTSET_MARKER : AUDIT_MARKER;

    LOGGER.info(
        marker,
        new MethodReturnedMessage(spy, methodCall, returnMsg, LOGGER.isDebugEnabled(marker)));
  }

  @Override
  public void constructorReturned(Spy spy, String constructionInfo) {
    //not yet used in the current implementation of log4jdbc
  }

  @Override
  public void sqlOccurred(Spy spy, String methodCall, String sql) {
    //not implemented,
    //as the features provided by the logger "jdbc.sqlonly" are not reproduced.
  }

  @Override
  public void sqlTimingOccurred(
      Spy spy, long execTime, String methodCall,
      String sql) {
    //test useless in the current implementation,
    //as if error level is not enabled for this logger,
    //the ConnectionSpy will not be used (see isjdbcLoggingEnabled())
    //might maybe change one day?
        /*if (!LOGGER.isErrorEnabled()) {
			return;
		}*/
    String operation = this.getSqlOperation(sql);
    if (Properties.isDumpSqlFilteringOn() && !this.shouldSqlBeLogged(operation)) {
      return;
    }

    Marker marker = this.getStatementMarker(operation);
    SqlTimingOccurredMessage message =
        new SqlTimingOccurredMessage(spy, execTime, methodCall, sql, LOGGER.isDebugEnabled(marker));

    if (Properties.isSqlTimingErrorThresholdEnabled() &&
        execTime >= Properties.getSqlTimingErrorThresholdMsec()) {

      LOGGER.error(marker, message);

    } else if (LOGGER.isWarnEnabled()) {
      if (Properties.isSqlTimingWarnThresholdEnabled() &&
          execTime >= Properties.getSqlTimingWarnThresholdMsec()) {

        LOGGER.warn(marker, message);
      } else {
        LOGGER.info(marker, message);
      }
    }
  }

  /**
   * Identify the operation performed by the sql statement
   * (either "select", "insert", "update", "delete", or "create").
   *
   * @param sql  A String representing the SQL statement to evaluate
   * @return A String representing the operation
   * 				performed by the sql statement
   * 				(either "select", "insert", "update", "delete", or "create"),
   * 				or an empty String if the operation could not be determined
   * 				(sql null, etc.)
   */
  private String getSqlOperation(String sql) {
    if (sql == null) {
      return "";
    }
    sql = sql.trim();

    if (sql.length() < 6) {
      return "";
    }
    return sql.substring(0, 6).toLowerCase();
  }

  /**
   * Return the appropriate Marker
   * (either SQL_MARKER, SELECT_MARKER,
   * INSERT_MARKER, UPDATE_MARKER, DELETE_MARKER,
   * or CREATE_MARKER) depending on the operation
   * performed by a SQL statement
   * (either "select", "insert", "update", "delete", or "create").
   * @param operation  a String representing the operation
   * 						performed by a SQL statement
   * 						(either "select", "insert", "update", "delete", or "create").
   * @return the appropriate Marker depending on the operation:
   * 						SELECT_MARKER if operation is equal to "select".
   * 						INSERT_MARKER if operation is equal to "insert".
   * 						UPDATE_MARKER if operation is equal to "update".
   * 						DELETE_MARKER if operation is equal to "delete".
   * 						CREATE_MARKER if operation is equal to "create".
   * 						SQL_MARKER otherwise.
   * @see #SQL_MARKER
   * @see #SELECT_MARKER
   * @see #INSERT_MARKER
   * @see #UPDATE_MARKER
   * @see #DELETE_MARKER
   * @see #CREATE_MARKER
   */
  private Marker getStatementMarker(String operation) {
    if (operation == null) {
      return SQL_MARKER;
    } else if ("select".equals(operation)) {
      return SELECT_MARKER;
    } else if ("insert".equals(operation)) {
      return INSERT_MARKER;
    } else if ("update".equals(operation)) {
      return UPDATE_MARKER;
    } else if ("delete".equals(operation)) {
      return DELETE_MARKER;
    } else if ("create".equals(operation)) {
      return CREATE_MARKER;
    }
    return SQL_MARKER;
  }

  /**
   * Determine if the given operation of an SQL statement
   * should be logged or not
   * based on the various DumpSqlXXXXXX flags.
   *
   * @param operation  A String representing the operation of a SQL statement
   * 					(either "select", "insert", "update", "delete", or "create").
   * @return  true if the SQL statement
   * 			executing the given operation should be logged, false if not.
   */
  private boolean shouldSqlBeLogged(String operation) {
    return
        (operation == null) ||
            (Properties.isDumpSqlSelect() && "select".equals(operation)) ||
            (Properties.isDumpSqlInsert() && "insert".equals(operation)) ||
            (Properties.isDumpSqlUpdate() && "update".equals(operation)) ||
            (Properties.isDumpSqlDelete() && "delete".equals(operation)) ||
            (Properties.isDumpSqlCreate() && "create".equals(operation));
  }

  @Override
  public void connectionOpened(Spy spy, long execTime) {
    this.connectionModified(spy, execTime, Operation.OPENING);
  }

  @Override
  public void connectionClosed(Spy spy, long execTime) {
    this.connectionModified(spy, execTime, Operation.CLOSING);
  }

  @Override
  public void connectionAborted(Spy spy, long execTime) {
    this.connectionModified(spy, execTime, Operation.ABORTING);
  }

  /**
   *
   * @param spy       ConnectionSpy that was opened or closed.
   * @param execTime    A long defining the time elapsed to open or close the connection in ms
   *            Caller should pass -1 if not used
   * @param operation   an int to define if the operation was to open, or to close connection.
   *            Should be equals to ConnectionMessage.OPENING
   *            if the operation was to open the connection,
   *            to ConnectionMessage.CLOSING if the operation was to close the connection.
   */
  private void connectionModified(Spy spy, long execTime, Operation operation) {
    LOGGER.info(
        CONNECTION_MARKER,
        new ConnectionMessage(spy, execTime, operation, LOGGER.isDebugEnabled(CONNECTION_MARKER)));
  }

  @Override
  public void debug(String msg) {
    DEBUGLOGGER.debug(msg);
  }

  @Override
  public boolean isResultSetCollectionEnabled() {
    return LOGGER.isInfoEnabled(RESULTSETTABLE_MARKER);
  }

  @Override
  public boolean isResultSetCollectionEnabledWithUnreadValueFillIn() {
    return LOGGER.isDebugEnabled(RESULTSETTABLE_MARKER);
  }

  @Override
  public void resultSetCollected(ResultSetCollector resultSetCollector) {

    String resultToPrint = new ResultSetCollectorPrinter().getResultSetToPrint(resultSetCollector);

    LOGGER.info(RESULTSETTABLE_MARKER, resultToPrint);

  }

}