mybatis打印的sql日志不写入到log文件的问题及解决
作者：0x2015
问题描述
环境： java 1.8、spring boot 2.2.4、mybatis-spring-boot-starter 2.1.1
在一次上线调bug中，想看看执行的sql语句，结果tail -100f这个日志文件发现sql语句没有输出到这个文件里面，然后在本地运行从console中又能看到有sql打印。
问题分析
第一时间想到会不会是logback配置不对
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<!-- 配置获取spring应用名称-->
<springProperty scope="context" name="springAppName" source="spring.application.name"/>
<!-- 日志输出文件的命名及地址-->
<property name="LOG_FILE" value="logs/${springAppName}-%d{yyyy-MM-dd}.log"/>
<!-- 控制台输出日志格式 -->
<property name="CONSOLE_LOG_PATTERN"
value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n"/>
<!-- 控制台输出级别及格式等 -->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>
<!-- 平台文件的输出配置：输出文件命名、输出级别等 -->
<appender name="flatfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${LOG_FILE}.gz</fileNamePattern>
<maxHistory>3</maxHistory>
</rollingPolicy>
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>
<!-- 配置日志输出级别 -->
<root level="DEBUG">
<appender-ref ref="console"/>
<appender-ref ref="flatfile"/>
</root>
</configuration>logback配置如上，就是两个appender，一个输console一个输file，都是debug级别，所以这个配置文件是没有问题的
然后发现到，console中打印的日志好像是被直接sout在上面的，不是logback打印的，所以肯定就不会输出到上面配置的文件里面啦
现在很好奇这个sout是从哪里打印出来的
下面使用了arthas的redefine
关于arthas： Arthas 是阿里巴巴最近才开源出来的一款 Java 诊断利器。主要是针对线上环境，也就是生产环境
git地址： https://github.com/alibaba/arthas
由于字符串拼接基本都是通过StringBuilder来实现的，所以这里redefine StringBuilder
@Override
public String toString() {
// Create a copy, don't share the array
String result = new String(value, 0, count);
if(result.contains("Preparing:")) {
System.err.println(result);
new Throwable().printStackTrace();
}
return result;
}这里将StringBuilder的toString方法加了点料，将preparing就是打印sql的地方，把堆栈打印了出来，javac编译后，然后redefine StringBuilder.class
redefine成功之后，再去触发sql打印
发现是从BaseJdbcLogger这里调用的
protected void debug(String text, boolean input) {
if (this.statementLog.isDebugEnabled()) {
this.statementLog.debug(this.prefix(input) + text);
}
}就是这个地方调用的debug，是statementLog这个对象的方法
public abstract class BaseJdbcLogger {
protected static final Set<String> SET_METHODS = new HashSet();
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 Log statementLog;
protected int queryStack;
public BaseJdbcLogger(Log log, int queryStack) {
this.statementLog = log;
if (queryStack == 0) {
this.queryStack = 1;
} else {
this.queryStack = queryStack;
}
}
……
}注意到这个statementLog和构造方法，statementLog是一个Log接口实现，是从构造方法中传入Log的实现类对象的
package org.apache.ibatis.logging;
public interface Log {
boolean isDebugEnabled();
boolean isTraceEnabled();
void error(String var1, Throwable var2);
void error(String var1);
void debug(String var1);
void trace(String var1);
void warn(String var1);
}它包含了四种日志级别，以及debug、trace开关
Log接口的实现类就是我们常用的日志框架的日志门面类slf4j、log4j2等等，这些日志门面会找到具体的日志实现框架，目前的环境就是slf4j -> logback这种实现
接下来就在构造方法里打断点debug
发现传入的是一个StdOutImpl，一看就是sout的实现
package org.apache.ibatis.logging.stdout;
import org.apache.ibatis.logging.Log;
public class StdOutImpl implements Log {
public StdOutImpl(String clazz) {
}
public boolean isDebugEnabled() {
return true;
}
public boolean isTraceEnabled() {
return true;
}
public void error(String s, Throwable e) {
System.err.println(s);
e.printStackTrace(System.err);
}
public void error(String s) {
System.err.println(s);
}
public void debug(String s) {
System.out.println(s);
}
public void trace(String s) {
System.out.println(s);
}
public void warn(String s) {
System.out.println(s);
}
}所以问题出在这里了，根据分析，这里应该传入Slf4jImpl这个实现才对，然后在spring boot的debug日志里输出了很多信息，搜索这个StdOutImpl
发现已经告诉了目前使用的是StdOutImpl，根据分析，问题很可能就出在了mybatis配置上
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration PUBLIC "-//mybatis.org//DTD Config 3.0//EN" "http://mybatis.org/dtd/mybatis-3-config.dtd">
<configuration>
<settings>
<setting name="cacheEnabled" value="true" />
<setting name="lazyLoadingEnabled" value="true" />
<setting name="multipleResultSetsEnabled" value="true" />
<setting name="useColumnLabel" value="true" />
<setting name="defaultExecutorType" value="REUSE" />
<setting name="defaultStatementTimeout" value="25000" />
<setting name="logImpl" value="STDOUT_LOGGING" />
<!-- 开启驼峰命名转换：Table(create_time) -> Entity(createTime) -->
<setting name="mapUnderscoreToCamelCase" value="true"/>
</settings>
</configuration>这就是该项目使用的mybatis的配置，发现了logImpl，stdout，应该就是在这里配置的
查文档发现这里可以配置这么多，所以改成SLF4J就ok了
这个实现类就成功变成了Slf4jImpl，日志文件里面也有了sql打印
问题解决
修改mybatis配置文件中的
<setting name="logImpl" value="STDOUT_LOGGING" />
变为
<setting name="logImpl" value="SLF4J" />
或者删掉也行
总结
sout输出的是不会记录在日志文件中的，必须使用log的方式才能记录，这也是我们在捕获异常或全局异常处理，要使用log.error("", e);替代e.printStackTrace();的原因
spring boot中mybatis的sql打印实际上就把logback配置修改为debug级别就可以了，
像mybatis配置logImpl，application.properties中写logging.level.com.xxx.dao=debug都是不必要的，除非需要一些细粒度的控制
特别注意：mybatis如果要配置logImpl的话尽量不要使用STDOUT_LOGGING！
以上仅为个人经验，希望能给大家一个参考，也希望大家多多支持脚本之家。