在特定环境只打印某个包下的sql语句到日志中

---

一.问题描述

工作上遇到的一个技术需求，在特定环境下打印特定某个包下面的sql语句，因为项目用的SpringBoot+Mybatis，mybatis里sql默认打印等级是DEBUG，但由于DEBUG级的无效信息太多，prod环境输出到日志文件的打印等级是INFO，现在问题的核心就是如何在特定环境下以INFO等级打印特定包下的sql。
问题标签： 多环境，限定包，sql打印，日志等级

二.方法探索

过程中看了很多方法，注有推荐的方法是可行的，其他方法存在相应缺陷，不一定能实现，可以拓宽思路。

1.修改logback配置以debug级别打印sql

SpeingBoot默认框架是SLF4J，实现是logback，SpringBoot 配置文件的加载顺序为logback.xml->application. properties->logback-spring.xml
dev环境下控制台输出STDOUT，打印级别为不过滤默认debugger

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">  
        <!-- encoder的默认实现类是ch.qos.logback.classic.encoder.PatternLayoutEncoder -->  
        <encoder>  
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n</pattern>  
        </encoder>  
    </appender> 

在prod环境下输出为FILE，打印级别为info，info以上的不输出

	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 		<file>${file}.${postfix}</file> -->
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>${file}_%d{yyyyMMdd}_%i${postfix}</fileNamePattern>
            <maxHistory>30</maxHistory>
		</rollingPolicy>
		<encoder>
			<pattern>${LOG_PATTERN}</pattern>
    	</encoder>
         <filter class="ch.qos.logback.classic.filter.LevelFilter">
             <level>INFO</level>
             <onMatch>ACCEPT</onMatch>
             <onMismatch>DENY</onMismatch>
         </filter>
	</appender>

在某个条件下打印某个包下的sql添加语句

# name是要打印的包，由于mybatissql级别为是debug，因此level也是debug
<logger name="com.spring.boot.springbootdemo.mapper" level="debug"/>

如果增加环境控制，在外面加上SpringProfile标签

<!--开发环境输出sql-->
    <springProfile name="dev">
        <logger name="com.spring.boot.springbootdemo.mapper" level="debug"/>
    </springProfile>

如果在prod环境也想使用，需要把

<level>INFO</level>

改成debug，并且把logback的根节点输出级别也改成debug

<!-- 日志输出级别 -->
<root level="debug">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="INFO-FILE"/>
</root>

到此为止，满足了以下几个要求：在特定环境输出某个包下的sql语句，但还有一个条件不满足，不是以INFO级别打印

2 修改mybatis配置在info等级打印日志

2.1 为什么mybatis的sql语句默认打印等级是debug

在前文多次提到mybatis的sql默认打印级别是debug，在此说一下原因

这是mybatis configuration.class配置类截图，里面有个属性是logImpl，也就是mybatis的日志实现，这里的实现提供了一些选项

可以看见常见的log4j，slf4j都有，也有不打印的情况，这些日志实现确定后，是否打印sql语句取决于这些实现类的属性isDebugEnabled

在PreparedStatementLogger.class中，可以看到如果isDebugEnabled=true，就以debug级别打印sql语句，这个是固定的

2.2 修改mybatis的配置在info打印sql

修改log-impl，根据项目情况在mybatis-setting.xml或者项目配置文件里修改

重写impl，将debug的方法重写为取决于slf4j的info级日志信息设置

package org.apache.ibatis.logging.mylog;

import lombok.extern.slf4j.Slf4j;
import org.apache.ibatis.logging.Log;

@Slf4j
public class MyLogImpl implements Log {
    public MyLogImpl(String clazz) {
        // Do Nothing
    }

    @Override
    public boolean isDebugEnabled() {
        // return log.isDebugEnabled();
        // 将debug级别输出权限改成info级别
        return log.isInfoEnabled();

    }

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

    @Override
    public void error(String s, Throwable e) {

    }

    @Override
    public void error(String s) {

    }


    @Override
    public void debug(String s) {
        // log.debug(s);
        // debug日志输出成info级别日志
        log.info(s);
    }

    @Override
    public void trace(String s) {

    }

    @Override
    public void warn(String s) {

    }

}

这个方法理论上是可行的，但是实操存在问题

3.Log4JDBC和p6sy

Log4JDBC和p6sy都是通过劫持数据源来实现的，在调用实际JDBC驱动前拦截调用的目标语，达到SQL语句日志记录的目的，两者使用方法差不多，都是添加依赖修改配置，log4jdbc是google开发的，在此基础上开发了log4jdbc-log4j2，在支持slf4j的同时，默认的日志实现使用了log4j2，推荐使用log4jdbc-log4j2。
官方文档地址：

log4jdbc-log4j2：http://log4jdbc.brunorozendo.com/
p6sy：https://p6spy.readthedocs.io/en/latest/configandusage.html

<!-- p6sy的依赖-->
<dependency>
	<groupId>p6spy</groupId>
	<artifactId>p6spy</artifactId>
	<version>3.7.0</version>
</dependency>

<!-- log4jdbc是google开发的，在此基础上开发了log4jdbc-log4j2，在支持slf4j的同时，默认的日志实现使用了log4j2-->
<dependency>
      <groupId>org.bgee.log4jdbc-log4j2</groupId>
      <artifactId>log4jdbc-log4j2-jdbc4.1</artifactId>
      <version>1.16</version>
</dependency>

然后需要修改DataSource的url和driver
log4jdbc-log4j2

spring:
  datasource:
  	  # 要加上log4jdbc
      jdbc:log4jdbc:mysql://127.0.0.1:3306/database?useUnicode=true&characterEncoding=utf-8&useSSL=false&serverTimezone=CTT
      username: root
      password: 123456
      # 修改驱动
      driver-class-name: net.sf.log4jdbc.sql.jdbcapi.DriverSpy

p6sy版：

spring:
  datasource:
  	  # 要加上p6sy
      url: jdbc:p6spy:mysql://127.0.0.1:3306/database?useUnicode=true&characterEncoding=utf-8&useSSL=false&serverTimezone=CTT
      username: root
      password: 123456
      # 修改驱动
      driver-class-name: com.p6spy.engine.spy.P6SpyDriver

两者还有一些其他的配置项，官网文档中有详细讲解，就不在此赘述了，作为比较成熟的sql日志管理系统他们能展示的信息比较全面，不仅能展示sql还有查询结果等数据都可以展示，打印等级是INFO，唯一值得注意的地方是他们会打印该项目内的所有sql，可能会占用资源，所以请仔细考虑在线上是否使用。

4.通过代码层面打印sql语句（推荐）

4.1 SpringBoot的Aop

再深度地剖析一下，mybatis打印sql日志的原理是JDK动态代理，在BaseExecutor.java类内，在与数据库进行连接时如果开启了isDebugEnabled就打印

代理对象ConnectionLogger

在springboot项目中，如果我们想以info等级打印对应的sql，可以采用AOP，详细代码如下。

@Slf4j
@Aspect
@Component
@ConditionalOnProperty(value = "sql.print.enable")
public class SqlExecuteStatementAop {
    @Resource
    private SqlSessionFactory sqlSessionFactory;
    @Pointcut("execution(* com.example.test.dao.*.*(..))")
    public void sqlAspect() {

    }

    @Before("sqlAspect()")
    public void doBefore() {
        log.info("--------------sql logging start--------------");
    }

    @After("sqlAspect()")
    public void doAfter() {
        log.info("--------------sql logging end--------------");
    }

    @Around("sqlAspect()")
    public Object around(ProceedingJoinPoint joinPoint){
        Object proceed = null;
        try {
            proceed = joinPoint.proceed();
        } catch (Throwable e) {
            log.error(e.getMessage(), e);
        }
        String mybatisExecuteStatement = SqlExecuteStatementUtils.getMybatisExecuteStatement(joinPoint, sqlSessionFactory);
        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        String methodName = signature.getMethod().getName();
        String className = signature.getMethod().getDeclaringClass().getName();
        log.info("print method name:{}, execute sql: {}", className + "." + methodName, mybatisExecuteStatement);
        return proceed;
    }
}

AOP是否启用采用@ConditionalOnProperty注解，该注解的作用是在properties文件内配置的特定条件下让配置类生效

获得sql语句的代码是

public class SqlExecuteStatementUtils {

    /**
     * 获取mybatis执行的sql语句
     * @param joinPoint
     * @param sqlSessionFactory
     * @return
     */
    public static String getMybatisExecuteStatement(ProceedingJoinPoint joinPoint, SqlSessionFactory sqlSessionFactory) {
        MethodSignature signature = (MethodSignature)joinPoint.getSignature();
        // 找到全限定类名
        Method method = signature.getMethod();
        String className = method.getDeclaringClass().getName();
        // 方法名
        String methodName = method.getName();
        String statementId = className + "." + methodName;
        Configuration configuration = sqlSessionFactory.getConfiguration();
        MappedStatement mappedStatement = configuration.getMappedStatement(statementId);
        Object[] pointArgs = joinPoint.getArgs();
        Annotation[][] methodParameterAnnotations = method.getParameterAnnotations();
        Map<String, Object> sqlParamMap = Maps.newHashMap();
        for (int i = 0; i < methodParameterAnnotations.length; i++) {
            Annotation[] annotations = methodParameterAnnotations[i];
            Object pointArg = pointArgs[i];
            if (annotations.length == 0) {
                // 这个参数没有注解
                if (pointArg instanceof Map) {
                    sqlParamMap.putAll((Map<? extends String, ?>) pointArg);
                } else{
                    Map<String, Object> beanToMap = BeanUtil.beanToMap(pointArg);
                    sqlParamMap.putAll(beanToMap);
                }
            } else {
                if (annotations[0] instanceof org.apache.ibatis.annotations.Param){
                    org.apache.ibatis.annotations.Param param = (org.apache.ibatis.annotations.Param) annotations[0];
                    String paramName = param.value();
                    sqlParamMap.put(paramName, pointArg);
                }
            }
        }

        return getSql(configuration, mappedStatement.getBoundSql(sqlParamMap));

    }


    /**
     * 对占位符进行对应的参数替换
     * @param configuration
     * @param boundSql
     * @return
     */
    private static String getSql(Configuration configuration, BoundSql boundSql) {
        Object parameterObject = boundSql.getParameterObject();
        List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
        String sql = boundSql.getSql().replaceAll("[\\s]+", " ");
        if (CollectionUtils.isNotEmpty(parameterMappings) && parameterObject != null) {
            TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();
            if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
                sql = sql.replaceFirst("\\?", getParameterValue(parameterObject));
            } else {
                MetaObject metaObject = configuration.newMetaObject(parameterObject);
                for (ParameterMapping parameterMapping : parameterMappings) {
                    String propertyName = parameterMapping.getProperty();
                    if (metaObject.hasGetter(propertyName)) {
                        Object obj = metaObject.getValue(propertyName);
                        sql = sql.replaceFirst("\\?", getParameterValue(obj));
                    } else if (boundSql.hasAdditionalParameter(propertyName)) {
                        Object obj = boundSql.getAdditionalParameter(propertyName);
                        sql = sql.replaceFirst("\\?", getParameterValue(obj));
                    }
                }
            }
        }
        return sql;
    }

	/**
     * 若为字符串或者日期类型，则在参数两边添加''
     *
     * @param object
     * @return
     */
    private static String getParameterValue(Object object) {
        String value = null;
        if (object instanceof String) {
            value = "'" + object + "'";
        } else if (object instanceof Date) {
            value = "'" + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date()) + "'";
        } else {
            if (object != null) {
                value = object.toString();
            } else {
                value = "";
            }
        }
        return value;
    }
}

4.2 Mybatis的 Interceptor

mybatis内有拦截器Interceptor

可以拦截的类型有如下四种
1.Executor：拦截执行器的方法。
2.ParameterHandler：拦截参数的处理。
3.ResultHandler：拦截结果集的处理。
4.StatementHandler：拦截Sql语法构建的处理。
在@Interceptor注解内还有@Signature注解，里面的参数有：
type：就是指定拦截器类型，Executor、ParameterHandler、StatementHandler、ResultSetHandler当中的一个
method：是拦截器类型中的方法，不是自己写的方法
args：是method中方法的入参
因为我们需要获得的是sql语句，那么拦截的类就是StatementHandler实现代码如下

@Slf4j
@Intercepts({
        @Signature(type = StatementHandler.class,
                method = "prepare",
                args = {Connection.class, Integer.class})})
public class MybatisSqlInterceptor implements Interceptor {

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        //type为StatementHandler，拦截的是生成sql语句的handler，默认拦截的是RoutingStatementHandler
        // 里面有个StatementHandler类型的delegate变量，其实现类是BaseStatementHandler，然后就到BaseStatementHandler的成员变量mappedStatement
        // mappedStatement表示的是一个增删改查的对象，里面有我们需要的sql语句,id就是我们需要的sql语句的唯一标识，全限定类名+方法名
        StatementHandler statementHandler = (StatementHandler) invocation.getTarget();
        MetaObject metaObjectHandler = SystemMetaObject.forObject(statementHandler);
        MappedStatement mappedStatement = (MappedStatement) metaObjectHandler.getValue("delegate.mappedStatement");
        // 获取请求时的参数
        Object parameterObject = statementHandler.getParameterHandler().getParameterObject();
        // 获取sql
        String sql = getSql(mappedStatement.getConfiguration(),  mappedStatement.getBoundSql(parameterObject));
        Object result = invocation.proceed();
        log.info("sql method：{}，sql statement : {} ", mappedStatement.getId(), sql);
        return result;
    }


    @Override
    public Object plugin(Object target) {
    	// 判断是否拦截这个类型对象（根据@Intercepts注解决定），然后决定是返回一个代理对象还是返回原对象。
        return (target instanceof StatementHandler) ? Plugin.wrap(target, this) : target;
    }


    @Override
    public void setProperties(Properties properties) {
    }

    /**
     * 对占位符进行对应的参数替换
     * @param configuration
     * @param boundSql
     * @return
     */
    private static String getSql(Configuration configuration, BoundSql boundSql) {
        Object parameterObject = boundSql.getParameterObject();
        List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
        String sql = boundSql.getSql().replaceAll("[\\s]+", " ");
        if (CollectionUtils.isNotEmpty(parameterMappings) && parameterObject != null) {
            TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();
            if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
                sql = sql.replaceFirst("\\?", getParameterValue(parameterObject));
            } else {
                MetaObject metaObject = configuration.newMetaObject(parameterObject);
                for (ParameterMapping parameterMapping : parameterMappings) {
                    String propertyName = parameterMapping.getProperty();
                    if (metaObject.hasGetter(propertyName)) {
                        Object obj = metaObject.getValue(propertyName);
                        sql = sql.replaceFirst("\\?", getParameterValue(obj));
                    } else if (boundSql.hasAdditionalParameter(propertyName)) {
                        Object obj = boundSql.getAdditionalParameter(propertyName);
                        sql = sql.replaceFirst("\\?", getParameterValue(obj));
                    }
                }
            }
        }
        return sql;
    }

    /**
     * 若为字符串或者日期类型，则在参数两边添加''
     *
     * @param object
     * @return
     */
    private static String getParameterValue(Object object) {
        String value = null;
        if (object instanceof String) {
            value = "'" + object + "'";
        } else if (object instanceof Date) {
            value = "'" + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date()) + "'";
        } else {
            if (object != null) {
                value = object.toString();
            } else {
                value = "";
            }
        }
        return value;
    }
}

拦截器需要注册到 Mybatis的SessionFactory中

@Configuration
public class MybatisConfiguration {
    @Autowired
    private SqlSessionFactory sqlSessionFactory;
    
    @PostConstruct
    public void init() {
        // 给sqlSessionFactory添加拦截器
        this.sqlSessionFactory.getConfiguration().addInterceptor(new MybatisSqlInterceptor());
    }
}

---

三.总结

推荐使用第四种方法的Interceptor来进行sql打印，代码实现可以满足本次需求的要求，其他方法或多或少存在问题，关于修改mybatis的配置我自己尝试是有问题的，如果有实现的同学欢迎在下面评论指出问题~