Reader entry: ���� 乱码详解

系统：Win10
JDK：1.8.0_333
IDEA：2020.3.4

1.问题描述

在一次写 MyBatis 项目工程的时候，使用 Logback 打印日志时，发现控制台有输出乱码，乱码如下

[DEBUG]  [main] o.a.i.l.LogFactory - Logging initialized using 'class org.apache.ibatis.logging.slf4j.Slf4jImpl' adapter. 
[DEBUG]  [main] o.a.i.io.VFS - Class not found: org.jboss.vfs.VFS 
[DEBUG]  [main] o.a.i.i.JBoss6VFS - JBoss 6 VFS API is not available in this environment. 
[DEBUG]  [main] o.a.i.io.VFS - Class not found: org.jboss.vfs.VirtualFile 
[DEBUG]  [main] o.a.i.io.VFS - VFS implementation org.apache.ibatis.io.JBoss6VFS is not valid in this environment. 
[DEBUG]  [main] o.a.i.io.VFS - Using VFS adapter org.apache.ibatis.io.DefaultVFS 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Find JAR URL: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/pojo 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Not a JAR: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/pojo 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: User.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Listing file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/pojo 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Find JAR URL: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/pojo/User.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Not a JAR: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/pojo/User.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: ����   4 I 
[DEBUG]  [main] o.a.i.i.ResolverUtil - Checking to see if class com.lijinjiang.pojo.User matches criteria [is assignable to Object] 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Find JAR URL: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Not a JAR: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: UserMapper.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: UserMapper.xml 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Listing file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Find JAR URL: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper/UserMapper.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Not a JAR: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper/UserMapper.class 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: ����   4  	  
[DEBUG]  [main] o.a.i.i.DefaultVFS - Find JAR URL: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper/UserMapper.xml 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Not a JAR: file:/C:/Programming/Workspace/IDEA/TestLogback/target/classes/com/lijinjiang/mapper/UserMapper.xml 
[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: <?xml version="1.0" encoding="UTF-8" ?> 
[DEBUG]  [main] o.a.i.i.ResolverUtil - Checking to see if class com.lijinjiang.mapper.UserMapper matches criteria [is assignable to Object] 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Opening JDBC Connection 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Created connection 1863702030. 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@6f15d60e] 
[DEBUG]  [main] c.l.m.U.selectAll - ==>  Preparing: select * from tb_user; 
[DEBUG]  [main] c.l.m.U.selectAll - ==> Parameters:  
[DEBUG]  [main] c.l.m.U.selectAll - <==      Total: 3 
[User{id=1, username='古天乐', password='123456', gender='男', address='香港'}, User{id=2, username='刘亦菲', password='123456', gender='女', address='湖北'}, User{id=3, username='胡歌', password='123456', gender='男', address='上海'}]
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Resetting autocommit to true on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@6f15d60e] 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Closing JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@6f15d60e] 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Returned connection 1863702030 to pool.

2.问题分析

先贴出来我的 mybatis 配置信息

    <!-- 类型别名 -->
    <typeAliases>
        <package name="com.lijinjiang.pojo"/>
    </typeAliases>

    <!-- 环境配置 -->
    <environments default="development">
        <environment id="development">
            <transactionManager type="JDBC"/>
            <dataSource type="POOLED">
                <property name="driver" value="com.mysql.cj.jdbc.Driver"/>
                <property name="url" value="jdbc:mysql://localhost:3306/mybatis"/>
                <property name="username" value="root"/>
                <property name="password" value="123456"/>
            </dataSource>
        </environment>
    </environments>

    <!-- 映射器 -->
    <mappers>
        <!-- 包扫描 -->
        <package name="com.lijinjiang.mapper"/>
    </mappers>

在一番尝试后，我发现，这里的乱码和 mybatis 的配置信息有关，当我的 类型别名（typeAliases）和 映射器（mappers）配置成包扫描模式的时候（package），就会出现这样的乱码
所以我尝试将这两个配置恢复成单个配置项

    <!-- 类型别名 -->
    <typeAliases>
        <typeAlias type="com.lijinjiang.pojo.User" alias="User"/>
    </typeAliases>

    <!-- 环境配置 -->
    <environments default="development">
        <environment id="development">
            <transactionManager type="JDBC"/>
            <dataSource type="POOLED">
                <property name="driver" value="com.mysql.cj.jdbc.Driver"/>
                <property name="url" value="jdbc:mysql://localhost:3306/mybatis"/>
                <property name="username" value="root"/>
                <property name="password" value="123456"/>
            </dataSource>
        </environment>
    </environments>

    <!-- 映射器 -->
    <mappers>
        <!-- 加载指定的 SQL 映射文件-->
        <mapper resource="com/lijinjiang/mapper/UserMapper.xml"/>
    </mappers>

然后就发现控制台的乱码果然就消失了

[DEBUG]  [main] o.a.i.l.LogFactory - Logging initialized using 'class org.apache.ibatis.logging.slf4j.Slf4jImpl' adapter. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Opening JDBC Connection 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Created connection 1626343059. 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@60f00693] 
[DEBUG]  [main] c.l.m.U.selectAll - ==>  Preparing: select * from tb_user; 
[DEBUG]  [main] c.l.m.U.selectAll - ==> Parameters:  
[DEBUG]  [main] c.l.m.U.selectAll - <==      Total: 3 
[User{id=1, username='古天乐', password='123456', gender='男', address='香港'}, User{id=2, username='刘亦菲', password='123456', gender='女', address='湖北'}, User{id=3, username='胡歌', password='123456', gender='男', address='上海'}]
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Resetting autocommit to true on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@60f00693] 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Closing JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@60f00693] 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Returned connection 1626343059 to pool. 

但是这种方法治标不治本，以后做大工程的时候，不可能一项一项配置别名和映射文件，所以我们得找出具体的原因，然后从根本上解决这个问题
这时候，我们回到打印乱码的位置，看下能不能获得啥有用的信息

[DEBUG]  [main] o.a.i.i.DefaultVFS - Reader entry: ����   4 I 

这里我们可以看到是 DefaultVFS 类输出的这条信息，那么 DefaultVFS 是什么呢？

VFS 全称是 Virtual File System，他是一个虚拟的文件系统，为读取不同存储介质中的文件和数据提供一个统一的API方法
在 mybatis 中，VFS 定义了访问程序宿主机资源的 API 接口，这些资源包括：jar 包，class 文件，配置文件等
mybatis 内置了两种 VFS 实现：JBoss6VFS 和 DefaultVFS

public static final Class<?>[] IMPLEMENTATIONS = { JBoss6VFS.class, DefaultVFS.class };

其中 JBoss6VFS 的实现依赖于 JBoss 6 的 VFS API，DefaultVFS 则是适用于大多数应用程序服务器的 VFS 的默认实现
这里打印乱码的就是 DefaultVFS ，我们就打开 DefaultVFS 文件，看看是哪里打印的这条信息
DefaultVFS 类的包路径为：org.apache.ibatis.io
我们通过打断点的方式进行调试，发现具体代码位置如下图所示

这里解释一下为什么这里会打印乱码现象
这里的 list 方法是用于递归获取指定路径下的所有资源列表
首先会把我们配置的包路径：com.lijinjiang.pojo 传递过来，找到了里面的 User.class，资源合法，放进 resources，然后下面会递归调用 list 方法，进入 User.class 内，这时候使用 readLine 方法读取一行数据就产生了乱码，还打印进了 debug 日志

3.问题解决

这里出现乱码的原因是 DefaultVFS 导致的，那么我们换成 JBoss6VFS 试下，不过它的实现依赖于 JBoss 6 的 VFS API，所以我们需要先在 pom 里配置 jboss-vfs 的依赖

<!-- 添加 jboss-vfs 依赖 -->
<dependency>
    <groupId>org.jboss</groupId>
    <artifactId>jboss-vfs</artifactId>
    <version>3.2.17.Final</version>
</dependency>

我们再运行一下程序就可以发现，乱码的日志不见了

[DEBUG]  [main] o.a.i.l.LogFactory - Logging initialized using 'class org.apache.ibatis.logging.slf4j.Slf4jImpl' adapter. 
[DEBUG]  [main] o.a.i.io.VFS - Using VFS adapter org.apache.ibatis.io.JBoss6VFS 
[DEBUG]  [main] o.a.i.i.ResolverUtil - Checking to see if class com.lijinjiang.pojo.User matches criteria [is assignable to Object] 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - PooledDataSource forcefully closed/removed all connections. 
[DEBUG]  [main] o.a.i.i.ResolverUtil - Checking to see if class com.lijinjiang.mapper.UserMapper matches criteria [is assignable to Object] 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Opening JDBC Connection 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Created connection 258535644. 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@f68f0dc] 
[DEBUG]  [main] c.l.m.U.selectAll - ==>  Preparing: select * from tb_user; 
[DEBUG]  [main] c.l.m.U.selectAll - ==> Parameters:  
[DEBUG]  [main] c.l.m.U.selectAll - <==      Total: 3 
[User{id=1, username='古天乐', password='123456', gender='男', address='香港'}, User{id=2, username='刘亦菲', password='123456', gender='女', address='湖北'}, User{id=3, username='胡歌', password='123456', gender='男', address='上海'}]
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Resetting autocommit to true on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@f68f0dc] 
[DEBUG]  [main] o.a.i.t.j.JdbcTransaction - Closing JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@f68f0dc] 
[DEBUG]  [main] o.a.i.d.p.PooledDataSource - Returned connection 258535644 to pool. 

那么为什么换成 JBoss6VFS 就不打印乱码了呢？它代码里都不调用打印日志功能，我不打印总不会出错吧

所以，只要配置 jboss-vfs 的依赖即可