曹工杂谈--使用mybatis的同窗，进来看看怎么在日志打印完整sql吧，在数据库可执行那种

时间  2020-01-02
标签 杂谈 使用 mybatis 同窗 进来 看看 怎么 日志 打印 完整 sql 数据库 可执行 那种 栏目 MyBatis 繁體版
原文   原文链接

前言

今天新年第一天，给你们拜个年，祝你们新的一年里，技术突突突，头发长长长！html

我们搞技术的，比较直接，那就开始吧。我给你们看看我demo工程的效果（代码下边会给你们的）：java

技术栈是mybatis/mybatis plus，spring boot ，日志是logback。git

其实这个痛点吧，我是一直有的，测试或者开发时，日志里每次打印的都是带?的sql，而后还得本身手动一个参数一个参数地贴过去，这真是一个体力活。虽然是体力活，仍是作了这么多年了，此次，终于决定不忍了。web

在弄这个以前呢，我知道idea里有个插件能够实现这个功能，mybatis-log-plugin，但我这边idea一直用不起，具体缘由不明，反正就是完整sql打印不出来。spring

而后我刚搜了下，mybatis plus也支持，加下面这样一行配置便可：sql

mybatis-plus:
  configuration:
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl

但我注意到，这个是打印到控制台的，我试了下，效果以下：
apache

我以为，这样挺好的，可是有优化空间：api

  1. console打印，不适用于开发环境和测试环境；本地调试还不错；
  2. 本地调试时，通常我只挂起当前线程，若是请求多了，这里的打印会很乱；分不清哪一个日志是我这个请求的，而不是其余线程打印的

我本身这个项目也用的mybatis-plus，所以，我最终配置是下面这样：缓存

mybatis-plus:
  configuration:
    log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl

使用slf4j打印，而不是console直接print。但这依然没有解决：拼装完整sql，并打印到日志的需求。mybatis

大致思路

由于是本身瞎摸索出来的方案，不保证是最优的，只能说：it works。

你们再看看，正常状况下，是会打印下面这样的sql的（mybatis默认支持）：

[http-nio-8083-exec-1] DEBUG  c.e.w.mapper.AppealDisposalOnOffMapper.selectList
                    - ==>  Preparing: SELECT appeal_disposal_on_off_id,disposal_on_off_status,appeal_on_off_status,user_id FROM appeal_disposal_on_off WHERE (disposal_on_off_status = ?)  [BaseJdbcLogger.java:143]
                    
[http-nio-8083-exec-1] DEBUG  c.e.w.mapper.AppealDisposalOnOffMapper.selectList
                    - ==> Parameters: 0(Integer) [BaseJdbcLogger.java:143]

即，默认打印出：一行preparedStatement的语句，带？；下一行就是对应的参数。

个人方案是，对logger进行动态代理，当调用logger.info/debug/...的时候，拦截之。

拦截后的逻辑，以下：

  1. 当打印的语句，以==> Preparing:开头时，将当前语句存放到线程局部变量中，假设为A；
  2. 当打印的语句，以==> Parameters:开头时，将当前线程局部变量中的A拿出来，和当前语句一块儿，拼成一个完整的sql，而后调用当前方法（记住，咱们动态代理了logger.info等方法）打印之。

画图解决：

上面的逻辑图，你们看着没问题吧，其实问题的关键变成了，怎么去生成这个logger的动态代理，且最重要的是，你生成的动态代理对象要怎么生效。

具体实现分析

要讲解这部分，咱们只能切入细节了，毕竟咱们得找到一个切入点，去使用咱们的动态代理logger。

你们应该记得，咱们平时使用slf4j时，生成logger是否是下面这样写（如今虽然用lombok了，本质没变）：

private static final Logger logger = LoggerFactory.getLogger(A.class);
public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

这一行里，getILoggerFactory就要去获取classpath中绑定的日志实现了，具体的过程，我在另外一篇里也有讲：
曹工改bug--此次，我遇到了一个难缠的栈溢出bug，仍是日志相关的，真的难

由于咱们用的logback，因此这里会进入到logback包内的（包名怎么是slf4j的？没错，这就是slf4j-api怎么去找实现类的核心，相似java的SPI机制，具体看上面的博文）：

logback-classic包内的：
org.slf4j.impl.StaticLoggerBinder#getSingleton
 public static StaticLoggerBinder getSingleton() {
        return SINGLETON;
 }
 进入上面代码前，会先执行静态代码：
 private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();
 static {
    SINGLETON.init();
 }

上面的静态代码块中，进行初始化：

void init() {
            try {
                new ContextInitializer(defaultLoggerContext).autoConfig();
            } catch (JoranException je) {
                Util.report("Failed to auto configure default logger context", je);
            }
            //核心代码
            contextSelectorBinder.init(defaultLoggerContext, KEY);
            initialized = true;
    }
ch.qos.logback.classic.util.ContextSelectorStaticBinder#init
public void init(LoggerContext defaultLoggerContext, Object key) {
        if (this.key == null) {
            this.key = key;
        }
        // 这个contextSelector很重要，loggerFactory就是调用它的方法来生成
        String contextSelectorStr = OptionHelper.getSystemProperty(ClassicConstants.LOGBACK_CONTEXT_SELECTOR);
        if (contextSelectorStr == null) {
            contextSelector = new DefaultContextSelector(defaultLoggerContext);
        } else if (contextSelectorStr.equals("JNDI")) {
            contextSelector = new ContextJNDISelector(defaultLoggerContext);
        } else {
            contextSelector = dynamicalContextSelector(defaultLoggerContext, contextSelectorStr);
        }
    }

通过我多方调试，发现这里的contextSelector，发现它很关键。它是个接口，方法以下：

/**
 * An interface that provides access to different contexts.
 * 
 * It is used by the LoggerFactory to access the context
 * it will use to retrieve loggers.
 *
 * @author Ceki Gülcü
 * @author Sébastien Pennec
 */
public interface ContextSelector {
    // 获取LoggerContext，这个LoggerContext其实就是LoggerFactory
    LoggerContext getLoggerContext();

    LoggerContext getLoggerContext(String name);

    LoggerContext getDefaultLoggerContext();

    LoggerContext detachLoggerContext(String loggerContextName);

    List<String> getContextNames();
}

你们注意，这个类的方法，LoggerContext getLoggerContext();，返回值是LoggerContext,这个返回值类型比较牛逼，由于它其实就是LoggerFactory。

public class LoggerContext extends ContextBase implements ILoggerFactory, LifeCycle

你们看到了，这个LoggerContext实现了ILoggerFactory：

public interface ILoggerFactory {
    // 这个东西，你们熟悉了噻，logger工厂啊
    public Logger getLogger(String name);
}

综上分析，咱们要换Logger，可能没那么容易，由于Logger，是ILoggerFactory调用getLogger得到的。

那么，咱们只能把原始的ILoggerFactory（假设为A）给它换了，生成一个ILoggerFactory的动态代理（假A），保证每次调用A的getLogger时，就会被假A拦截。而后咱们在拦截的逻辑中，先使用A获取到原始logger，而后生成对原始logger进行动态代理的logger。

因此，如今完整的逻辑是这样：

问题，如今就变成了，怎么去生成org.slf4j.ILoggerFactory的动态代理，由于咱们须要这个原始的factory，否则咱们做为动态代理，本身也不知道怎么去生成Logger。

前面你们也看到了，

LoggerContext知足要求，那咱们只要在能拿到LoggerContext的地方，处理下就好了。

能拿到LoggerContext的地方，就是ContextSelector。

你们回头再看看以前那段代码：

public void init(LoggerContext defaultLoggerContext, Object key) throws ClassNotFoundException, NoSuchMethodException, InstantiationException,
                    IllegalAccessException, InvocationTargetException {
        if (this.key == null) {
            this.key = key;
        }
        //扩展点就在这里了，这里会去取环境变量，若是取不到，就用默认的，取到了，就用环境变量里的类
        String contextSelectorStr = OptionHelper.getSystemProperty(ClassicConstants.LOGBACK_CONTEXT_SELECTOR);
        if (contextSelectorStr == null) {
           A： contextSelector = new DefaultContextSelector(defaultLoggerContext);
        } else if (contextSelectorStr.equals("JNDI")) {
           B： contextSelector = new ContextJNDISelector(defaultLoggerContext);
        } else {
           C： contextSelector = dynamicalContextSelector(defaultLoggerContext, contextSelectorStr);
        }
    }

这里就是扩展点，咱们本身设置一个环境变量ClassicConstants.LOGBACK_CONTEXT_SELECTOR，就不会走A逻辑，而是走上面的C逻辑。具体的里面很简单，就是根据环境变量的值，去new一个对应的contextSelector。

具体实现步骤1--指定环境变量

@SpringBootApplication
@MapperScan("com.example.webdemo.mapper")
public class WebDemoApplicationUsingMybatisPlus {

    private static Logger log= null;
    static {
       // 这里设置环境变量，指向咱们自定义的class System.setProperty(ClassicConstants.LOGBACK_CONTEXT_SELECTOR,"com.example.webdemo.util.CustomDefaultContextSelector");
        log = LoggerFactory.getLogger(WebDemoApplicationUsingMybatisPlus.class);
    }

    public static void main(String[] args) {
        ConfigurableApplicationContext context = SpringApplication.run(WebDemoApplicationUsingMybatisPlus.class, args);
    }

}

具体实现步骤2--实现自定义的context-selector

package com.example.webdemo.util;

import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.selector.ContextSelector;
import org.springframework.cglib.proxy.Enhancer;
import org.springframework.cglib.proxy.MethodInterceptor;
import org.springframework.cglib.proxy.MethodProxy;

public class CustomDefaultContextSelector implements ContextSelector, MethodInterceptor {

    private LoggerContext defaultLoggerContext;

    private LoggerContext proxyedDefaultLoggerContext;

    private static ConcurrentHashMap<String, org.slf4j.Logger> cachedLogger = new ConcurrentHashMap<>(1000);


    public CustomDefaultContextSelector(LoggerContext context) {
        //1：原始的LoggerContext，框架会传进来
        this.defaultLoggerContext = context;
    }

    @Override
    public LoggerContext getLoggerContext() {
        return getDefaultLoggerContext();
    }

    @Override
    public LoggerContext getDefaultLoggerContext() {
        if (proxyedDefaultLoggerContext == null) {
            //2：咱们这里，将原始的LogegrContext进行代理，这里返回代理过的对象，完成偷天换日的效果，callback就设为本身
            Enhancer enhancer = new Enhancer();
            enhancer.setSuperclass(defaultLoggerContext.getClass());
            enhancer.setCallback(this);
            proxyedDefaultLoggerContext = (LoggerContext) enhancer.create();
        }
        return proxyedDefaultLoggerContext;
    }

    @Override
    public Object intercept(Object o, Method method, Object[] args, MethodProxy methodProxy) throws Throwable {
        Object result;
        result = methodProxy.invokeSuper(o,args);
        //3：当原始的LoggerContext的getLogger被调用时，生成一个动态代理的Logger，会组装sql日志那种
        if (Objects.equals(method.getReturnType().getName(), org.slf4j.Logger.class.getName()) && Objects.equals(method.getName(), "getLogger")) {
            org.slf4j.Logger logger = (org.slf4j.Logger) result;
            String loggerName = logger.getName();

            /**
             * 只关心mybatis层的logger，mybatis层的logger的包名，咱们这边是固定的包下面
             * 若是不是这个包下的，直接返回
             */
            if (!loggerName.startsWith("com.example.webdemo.mapper")) {
                return result;
            }

            /**
             * 对mybatis mapper的log，须要进行代理；代理后的对象，咱们暂存一下，省得每次都建立代理对象
             * 从缓存获取代理logger
             */
            if (cachedLogger.get(loggerName) != null) {
                return cachedLogger.get(loggerName);
            }

            CustomLoggerInterceptor customLoggerInterceptor = new CustomLoggerInterceptor();
            customLoggerInterceptor.setLogger((Logger) result);
            Object newProxyInstance = Proxy.newProxyInstance(result.getClass().getClassLoader(), result.getClass().getInterfaces(), customLoggerInterceptor);

            cachedLogger.put(loggerName, (org.slf4j.Logger) newProxyInstance);

            return newProxyInstance;
        }

        return result;
    }

}

这里作了一点优化，将代理Logger进行了缓存，同名的logger只会有一个。

具体实现步骤3--logger的动态代理的逻辑

//摘录了一部分，由于处理字符串比较麻烦，因此代码多一点，这里就不贴出来了，你们本身去clone哈
private String assemblyCompleteMybatisQueryLog(Object[] args) {
        if (args != null && args.length > 1) {
            if (!(args[0] instanceof BasicMarker)) {
                return null;
            }
            /**
             * marker不匹配，直接返回
             */
            BasicMarker arg = (BasicMarker) args[0];
            if (!Objects.equals(arg.getName(), "MYBATIS")) {
                return null;
            }

            String message = null;
            for (int i = (args.length - 1); i >= 0 ; i--) {
                if (args[i] != null && args[i] instanceof String) {
                    message = (String) args[i];
                    break;
                }
            }
            if (message == null) {
                return null;
            }
            // 这里就是判断当前打印的sql是啥，进行对应的处理
            if (message.startsWith("==>  Preparing:")) {
                String newMessage = message.substring("==>  Preparing:".length()).trim();
                SQL_LOG_VO_THREAD_LOCAL.get().setPrepareSqlStr(newMessage);
            } else if (message.startsWith("==> Parameters:")) {
                try {
                    return populateSqlWithParams(message);
                } catch (Exception e) {
                    logger.error("{}",e);
                }finally {
                    SQL_LOG_VO_THREAD_LOCAL.remove();
                }
            }
        }

        return null;
    }

总结

源码地址奉上，你们deug一下，立刻就明白了。

针对mybatis的：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/log-complete-sql-demo-mybatis

针对mybatis-plus的：

https://gitee.com/ckl111/all-simple-demo-in-work/tree/master/log-complete-sql-demo-mybatis-plus

具体就这么多吧，你们把3个工具类拷过去基本就能用了，而后改成本身mapper的包名，你们以为有帮助，请点个赞哈，大过年的，哈哈！

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程