MyBatis设计思想(2)——日志模块

一. 痛点分析

作为一个成熟的中间件，日志功能是必不可少的。那么，MyBatis是要自己实现日志功能，还是集成第三方的日志呢？MyBatis选择了集成第三方日志框架。
第三方的日志框架种类繁多，且级别定义、实现方式都不一样，每个使用MyBatis的业务都可能采用不同的日志组件，那MyBatis如何进行兼容？如果业务方引入了多个日志框架，MyBatis按照什么优先级进行选择？
MyBatis的核心流程，包括SQL拼接、SQL执行、结果集映射等关键步骤，都是需要打印日志的，那在核心流程中显式log.info(“xxx”)有点不太合适，如何将日志打印优雅地嵌入到核心流程中？

二. 适配器模式

适配器模式的作用：将一个接口转换成满足客户端期望的另一个接口，使得接口不兼容的那些类可以一起工作。

角色：

Target：目标接口，定义了客户端所需要的接口。
Adaptee：被适配者，它自身有满足客户端需求的功能，但是接口定义与Target并不兼容，需要进行适配。
Adapter：适配器，对Adaptee进行适配，使其满足Target的定义，供客户端使用。

三. MyBatis集成第三方日志框架

MyBatis定义了Log接口，并给出了debug、trace、error、warn四种日志级别：

/**
 * @author Clinton Begin
 *
 * MyBatis日志接口定义
 */
public interface Log {

  boolean isDebugEnabled();

  boolean isTraceEnabled();

  void error(String s, Throwable e);

  void error(String s);

  void debug(String s);

  void trace(String s);

  void warn(String s);

}

这其实是所有主流日志框架所支持的级别的交集。
MyBatis为大部分主流的日志框架，都实现了Adapter。以Log4j为例：

/**
 * @author Eduardo Macarron
 *
 * MyBatis为Log4j实现的Adapter
 */
public class Log4jImpl implements Log {

  private static final String FQCN = Log4jImpl.class.getName();

  //内部维护log4j的Logger实例
  private final Logger log;

  public Log4jImpl(String clazz) {
    log = Logger.getLogger(clazz);
  }

  @Override
  public boolean isDebugEnabled() {
    return log.isDebugEnabled();
  }

  @Override
  public boolean isTraceEnabled() {
    return log.isTraceEnabled();
  }

  @Override
  public void error(String s, Throwable e) {
    log.log(FQCN, Level.ERROR, s, e);
  }

  @Override
  public void error(String s) {
    log.log(FQCN, Level.ERROR, s, null);
  }

  @Override
  public void debug(String s) {
    log.log(FQCN, Level.DEBUG, s, null);
  }

  @Override
  public void trace(String s) {
    log.log(FQCN, Level.TRACE, s, null);
  }

  @Override
  public void warn(String s) {
    log.log(FQCN, Level.WARN, s, null);
  }

}

日志模块实现了适配器模式

Log = Target
Logger(log4j) = Adaptee
Log4jImpl = Adapter
日志实现类的选择

/**
 * @author Clinton Begin
 * @author Eduardo Macarron
 *
 * 日志工厂,通过getLog()方法获取日志实现类
 */
public final class LogFactory {

  /**
   * Marker to be used by logging implementations that support markers.
   */
  public static final String MARKER = "MYBATIS";

  private static Constructor<? extends Log> logConstructor;

  static {
    //按照顺序,依次尝试加载Log实现类
    //优先级为:slf4j -> commons-logging -> log4j2 -> log4j -> jdk-logging -> no-logging
    tryImplementation(LogFactory::useSlf4jLogging);
    tryImplementation(LogFactory::useCommonsLogging);
    tryImplementation(LogFactory::useLog4J2Logging);
    tryImplementation(LogFactory::useLog4JLogging);
    tryImplementation(LogFactory::useJdkLogging);
    tryImplementation(LogFactory::useNoLogging);
  }

  private LogFactory() {
    // disable construction
  }

  public static Log getLog(Class<?> clazz) {
    return getLog(clazz.getName());
  }

  public static Log getLog(String logger) {
    try {
      return logConstructor.newInstance(logger);
    } catch (Throwable t) {
      throw new LogException("Error creating logger for logger " + logger + ".  Cause: " + t, t);
    }
  }

  public static synchronized void useCustomLogging(Class<? extends Log> clazz) {
    setImplementation(clazz);
  }

  public static synchronized void useSlf4jLogging() {
    setImplementation(org.apache.ibatis.logging.slf4j.Slf4jImpl.class);
  }

  public static synchronized void useCommonsLogging() {
    setImplementation(org.apache.ibatis.logging.commons.JakartaCommonsLoggingImpl.class);
  }

  public static synchronized void useLog4JLogging() {
    setImplementation(org.apache.ibatis.logging.log4j.Log4jImpl.class);
  }

  public static synchronized void useLog4J2Logging() {
    setImplementation(org.apache.ibatis.logging.log4j2.Log4j2Impl.class);
  }

  public static synchronized void useJdkLogging() {
    setImplementation(org.apache.ibatis.logging.jdk14.Jdk14LoggingImpl.class);
  }

  public static synchronized void useStdOutLogging() {
    setImplementation(org.apache.ibatis.logging.stdout.StdOutImpl.class);
  }

  public static synchronized void useNoLogging() {
    setImplementation(org.apache.ibatis.logging.nologging.NoLoggingImpl.class);
  }

  private static void tryImplementation(Runnable runnable) {
    if (logConstructor == null) {
      try {
        runnable.run();
      } catch (Throwable t) {
        // ignore
      }
    }
  }

  private static void setImplementation(Class<? extends Log> implClass) {
    try {
      //查找指定实现类的构造器
      Constructor<? extends Log> candidate = implClass.getConstructor(String.class);
      Log log = candidate.newInstance(LogFactory.class.getName());
      if (log.isDebugEnabled()) {
        log.debug("Logging initialized using '" + implClass + "' adapter.");
      }
      logConstructor = candidate;
    } catch (Throwable t) {
      throw new LogException("Error setting Log implementation.  Cause: " + t, t);
    }
  }

}

这里还有一个点，NoLoggingImpl是一种Null Object Pattern(空对象模式)，也实现了目标接口，内部就是Do Nothing，这样客户端可以减少很多判空操作。

/**
 * @author Clinton Begin
 *
 * 空Log实现, Null Object Pattern
 */
public class NoLoggingImpl implements Log {

  public NoLoggingImpl(String clazz) {
    // Do Nothing
  }

  @Override
  public boolean isDebugEnabled() {
    return false;
  }

  @Override
  public boolean isTraceEnabled() {
    return false;
  }

  @Override
  public void error(String s, Throwable e) {
    // Do Nothing
  }

  @Override
  public void error(String s) {
    // Do Nothing
  }

  @Override
  public void debug(String s) {
    // Do Nothing
  }

  @Override
  public void trace(String s) {
    // Do Nothing
  }

  @Override
  public void warn(String s) {
    // Do Nothing
  }

}

四. 优雅地打印日志

代理模式：给某一个对象提供一个代理，并由代理对象控制对原对象的访问引用。代理对象可以在原对象的基础上，进行一些功能上的增强，而这些增强对客户端来说是无感知的。

MyBatis内部需要打印日志的地方
1. 创建PrepareStatement时，打印待执行的 SQL 语句。
2. 访问数据库时，打印参数的类型和值。
3. 查询出结果集后，打印结果数据条数。
MyBatis的日志增强器

BaseJdbcLogger：所有日志增强器的抽象父类,用于记录JDBC那些需要增强的方法,并保存运行期间的SQL参数信息。

/**
 * Base class for proxies to do logging.
 *
 * @author Clinton Begin
 * @author Eduardo Macarron
 *
 * 所有日志增强器的抽象父类,用于记录JDBC那些需要增强的方法,并保存运行期间的SQL参数信息
 */
public abstract class BaseJdbcLogger {

  protected static final Set<String> SET_METHODS;
  protected static final Set<String> EXECUTE_METHODS = new HashSet<>();

  private final Map<Object, Object> columnMap = new HashMap<>();

  private final List<Object> columnNames = new ArrayList<>();
  private final List<Object> columnValues = new ArrayList<>();

  protected final Log statementLog;
  protected final int queryStack;

  /*
   * Default constructor
   */
  public BaseJdbcLogger(Log log, int queryStack) {
    this.statementLog = log;
    if (queryStack == 0) {
      this.queryStack = 1;
    } else {
      this.queryStack = queryStack;
    }
  }

  static {
    //记录PreparedStatement中的setXXX()方法
    SET_METHODS = Arrays.stream(PreparedStatement.class.getDeclaredMethods())
            .filter(method -> method.getName().startsWith("set"))
            .filter(method -> method.getParameterCount() > 1)
            .map(Method::getName)
            .collect(Collectors.toSet());

    //记录executeXXX()方法
    EXECUTE_METHODS.add("execute");
    EXECUTE_METHODS.add("executeUpdate");
    EXECUTE_METHODS.add("executeQuery");
    EXECUTE_METHODS.add("addBatch");
  }

  protected void setColumn(Object key, Object value) {
    columnMap.put(key, value);
    columnNames.add(key);
    columnValues.add(value);
  }

  protected Object getColumn(Object key) {
    return columnMap.get(key);
  }

  protected String getParameterValueString() {
    List<Object> typeList = new ArrayList<>(columnValues.size());
    for (Object value : columnValues) {
      if (value == null) {
        typeList.add("null");
      } else {
        typeList.add(objectValueString(value) + "(" + value.getClass().getSimpleName() + ")");
      }
    }
    final String parameters = typeList.toString();
    return parameters.substring(1, parameters.length() - 1);
  }

  protected String objectValueString(Object value) {
    if (value instanceof Array) {
      try {
        return ArrayUtil.toString(((Array) value).getArray());
      } catch (SQLException e) {
        return value.toString();
      }
    }
    return value.toString();
  }

  protected String getColumnString() {
    return columnNames.toString();
  }

  protected void clearColumnInfo() {
    columnMap.clear();
    columnNames.clear();
    columnValues.clear();
  }

  protected String removeExtraWhitespace(String original) {
    return SqlSourceBuilder.removeExtraWhitespaces(original);
  }

  protected boolean isDebugEnabled() {
    return statementLog.isDebugEnabled();
  }

  protected boolean isTraceEnabled() {
    return statementLog.isTraceEnabled();
  }

  protected void debug(String text, boolean input) {
    if (statementLog.isDebugEnabled()) {
      statementLog.debug(prefix(input) + text);
    }
  }

  protected void trace(String text, boolean input) {
    if (statementLog.isTraceEnabled()) {
      statementLog.trace(prefix(input) + text);
    }
  }

  private String prefix(boolean isInput) {
    char[] buffer = new char[queryStack * 2 + 2];
    Arrays.fill(buffer, '=');
    buffer[queryStack * 2 + 1] = ' ';
    if (isInput) {
      buffer[queryStack * 2] = '>';
    } else {
      buffer[0] = '<';
    }
    return new String(buffer);
  }

}

ConnectionLogger：数据库连接的日志增强器,打印PreparedStatement信息,并通过动态代理方式,创建具有打印日志功能的PreparedStatement、Statement等。

/**
 * Connection proxy to add logging.
 *
 * @author Clinton Begin
 * @author Eduardo Macarron
 *
 * 数据库连接的日志增强器,打印PreparedStatement信息,并通过动态代理方式,创建具有打印日志功能的PreparedStatement、Statement等
 */
public final class ConnectionLogger extends BaseJdbcLogger implements InvocationHandler {

  //内部维护原始的数据库连接
  private final Connection connection;

  private ConnectionLogger(Connection conn, Log statementLog, int queryStack) {
    super(statementLog, queryStack);
    this.connection = conn;
  }

  @Override
  public Object invoke(Object proxy, Method method, Object[] params)
      throws Throwable {
    try {
      //1. 对于Object中定义的方法,不进行拦截
      if (Object.class.equals(method.getDeclaringClass())) {
        return method.invoke(this, params);
      }

      //2. 拦截prepareStatement()、prepareCall()方法,打印SQL信息,并返回PreparedStatementLogger增强器
      if ("prepareStatement".equals(method.getName()) || "prepareCall".equals(method.getName())) {
        if (isDebugEnabled()) {
          debug(" Preparing: " + removeExtraWhitespace((String) params[0]), true);
        }
        PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
        stmt = PreparedStatementLogger.newInstance(stmt, statementLog, queryStack);
        return stmt;
      }
      //3. 拦截createStatement()方法,返回StatementLogger增强器
      else if ("createStatement".equals(method.getName())) {
        Statement stmt = (Statement) method.invoke(connection, params);
        stmt = StatementLogger.newInstance(stmt, statementLog, queryStack);
        return stmt;
      }
      //4. 对于普通的Connection中的方法,直接调用
      else {
        return method.invoke(connection, params);
      }
    } catch (Throwable t) {
      throw ExceptionUtil.unwrapThrowable(t);
    }
  }

  /**
   * Creates a logging version of a connection.
   *
   * @param conn
   *          the original connection
   * @param statementLog
   *          the statement log
   * @param queryStack
   *          the query stack
   * @return the connection with logging
   */
  public static Connection newInstance(Connection conn, Log statementLog, int queryStack) {
    InvocationHandler handler = new ConnectionLogger(conn, statementLog, queryStack);
    ClassLoader cl = Connection.class.getClassLoader();
    return (Connection) Proxy.newProxyInstance(cl, new Class[]{Connection.class}, handler);
  }

  /**
   * return the wrapped connection.
   *
   * @return the connection
   */
  public Connection getConnection() {
    return connection;
  }

}

PreparedStatementLogger：PreparedStatement日志增强器,主要功能包括
1. 打印PreparedStatement中的动态参数信息。
2. 拦截setXXX()方法,记录封装的参数。
3. 创建ResultSetLogger增强器,使得对于结果集的操作具备日志打印的功能。

/**
 * PreparedStatement proxy to add logging.
 *
 * @author Clinton Begin
 * @author Eduardo Macarron
 *
 * PreparedStatement日志增强器,主要功能包括:
 * 1. 打印PreparedStatement中的动态参数信息
 * 2. 拦截setXXX()方法,记录封装的参数
 * 3. 创建ResultSetLogger增强器,使得对于结果集的操作具备日志打印的功能
 */
public final class PreparedStatementLogger extends BaseJdbcLogger implements InvocationHandler {

  //内部维护PreparedStatement对象
  private final PreparedStatement statement;

  private PreparedStatementLogger(PreparedStatement stmt, Log statementLog, int queryStack) {
    super(statementLog, queryStack);
    this.statement = stmt;
  }

  @Override
  public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
    try {
      //1. Object中定义的方法不拦截
      if (Object.class.equals(method.getDeclaringClass())) {
        return method.invoke(this, params);
      }

      //2. 拦截executeXXX()方法,打印参数信息
      if (EXECUTE_METHODS.contains(method.getName())) {
        if (isDebugEnabled()) {
          debug("Parameters: " + getParameterValueString(), true);
        }
        clearColumnInfo();
        if ("executeQuery".equals(method.getName())) {
          ResultSet rs = (ResultSet) method.invoke(statement, params);
          return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
        } else {
          return method.invoke(statement, params);
        }
      }
      //3. 拦截setXXX()方法,记录动态参数
      else if (SET_METHODS.contains(method.getName())) {
        if ("setNull".equals(method.getName())) {
          setColumn(params[0], null);
        } else {
          setColumn(params[0], params[1]);
        }
        return method.invoke(statement, params);
      }

      //4. 拦截getResultSet()方法,返回ResultSetLogger增强器
      else if ("getResultSet".equals(method.getName())) {
        ResultSet rs = (ResultSet) method.invoke(statement, params);
        return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
      }

      //5. 拦截getUpdateCount()方法,打印update操作影响的记录行数
      else if ("getUpdateCount".equals(method.getName())) {
        int updateCount = (Integer) method.invoke(statement, params);
        if (updateCount != -1) {
          debug("   Updates: " + updateCount, false);
        }
        return updateCount;
      }
      //6. 普通方法,直接调用PreparedStatement
      else {
        return method.invoke(statement, params);
      }
    } catch (Throwable t) {
      throw ExceptionUtil.unwrapThrowable(t);
    }
  }

  /**
   * Creates a logging version of a PreparedStatement.
   *
   * @param stmt - the statement
   * @param statementLog - the statement log
   * @param queryStack - the query stack
   * @return - the proxy
   */
  public static PreparedStatement newInstance(PreparedStatement stmt, Log statementLog, int queryStack) {
    InvocationHandler handler = new PreparedStatementLogger(stmt, statementLog, queryStack);
    ClassLoader cl = PreparedStatement.class.getClassLoader();
    return (PreparedStatement) Proxy.newProxyInstance(cl, new Class[]{PreparedStatement.class, CallableStatement.class}, handler);
  }

  /**
   * Return the wrapped prepared statement.
   *
   * @return the PreparedStatement
   */
  public PreparedStatement getPreparedStatement() {
    return statement;
  }

}

ResultSetLogger：结果集日志增强器,主要用于打印结果集的总记录数。

/**
 * ResultSet proxy to add logging.
 *
 * @author Clinton Begin
 * @author Eduardo Macarron
 *
 * 结果集日志增强器,主要用于打印结果集的总记录数
 */
public final class ResultSetLogger extends BaseJdbcLogger implements InvocationHandler {

  private static final Set<Integer> BLOB_TYPES = new HashSet<>();
  private boolean first = true;
  private int rows;
  private final ResultSet rs;
  private final Set<Integer> blobColumns = new HashSet<>();

  static {
    BLOB_TYPES.add(Types.BINARY);
    BLOB_TYPES.add(Types.BLOB);
    BLOB_TYPES.add(Types.CLOB);
    BLOB_TYPES.add(Types.LONGNVARCHAR);
    BLOB_TYPES.add(Types.LONGVARBINARY);
    BLOB_TYPES.add(Types.LONGVARCHAR);
    BLOB_TYPES.add(Types.NCLOB);
    BLOB_TYPES.add(Types.VARBINARY);
  }

  private ResultSetLogger(ResultSet rs, Log statementLog, int queryStack) {
    super(statementLog, queryStack);
    this.rs = rs;
  }

  @Override
  public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
    try {
      //1. Object中定义的方法不拦截
      if (Object.class.equals(method.getDeclaringClass())) {
        return method.invoke(this, params);
      }

      //2. 拦截next()方法,记录总记录数,并打印
      Object o = method.invoke(rs, params);
      if ("next".equals(method.getName())) {
        if ((Boolean) o) {
          rows++;
          if (isTraceEnabled()) {
            ResultSetMetaData rsmd = rs.getMetaData();
            final int columnCount = rsmd.getColumnCount();
            if (first) {
              first = false;
              printColumnHeaders(rsmd, columnCount);
            }
            printColumnValues(columnCount);
          }
        } else {
          debug("     Total: " + rows, false);
        }
      }
      clearColumnInfo();
      return o;
    } catch (Throwable t) {
      throw ExceptionUtil.unwrapThrowable(t);
    }
  }

  private void printColumnHeaders(ResultSetMetaData rsmd, int columnCount) throws SQLException {
    StringJoiner row = new StringJoiner(", ", "   Columns: ", "");
    for (int i = 1; i <= columnCount; i++) {
      if (BLOB_TYPES.contains(rsmd.getColumnType(i))) {
        blobColumns.add(i);
      }
      row.add(rsmd.getColumnLabel(i));
    }
    trace(row.toString(), false);
  }

  private void printColumnValues(int columnCount) {
    StringJoiner row = new StringJoiner(", ", "       Row: ", "");
    for (int i = 1; i <= columnCount; i++) {
      try {
        if (blobColumns.contains(i)) {
          row.add("<<BLOB>>");
        } else {
          row.add(rs.getString(i));
        }
      } catch (SQLException e) {
        // generally can't call getString() on a BLOB column
        row.add("<<Cannot Display>>");
      }
    }
    trace(row.toString(), false);
  }

  /**
   * Creates a logging version of a ResultSet.
   *
   * @param rs
   *          the ResultSet to proxy
   * @param statementLog
   *          the statement log
   * @param queryStack
   *          the query stack
   * @return the ResultSet with logging
   */
  public static ResultSet newInstance(ResultSet rs, Log statementLog, int queryStack) {
    InvocationHandler handler = new ResultSetLogger(rs, statementLog, queryStack);
    ClassLoader cl = ResultSet.class.getClassLoader();
    return (ResultSet) Proxy.newProxyInstance(cl, new Class[]{ResultSet.class}, handler);
  }

  /**
   * Get the wrapped result set.
   *
   * @return the resultSet
   */
  public ResultSet getRs() {
    return rs;
  }

}

日志功能的优雅嵌入：MyBatis有个核心的组件Executor，主要的处理逻辑都是在Executor中实现的，日志的打印也是在这里，具体可见org.apache.ibatis.executor.BaseExecutor#getConnection()方法：

 //获取数据库连接
  protected Connection getConnection(Log statementLog) throws SQLException {
    //1. 通过事务获取JDBC Connection
    Connection connection = transaction.getConnection();

    //2. 如果开启了日志,则返回ConnectionLogger增强器
    if (statementLog.isDebugEnabled()) {
      return ConnectionLogger.newInstance(connection, statementLog, queryStack);
    } else {
      return connection;
    }
  }

这里获取了ConnectionLogger后，后续的PreparedStatement、ResultSet也就会具备日志打印的功能了。