记一次推送elk失败的问题

前一段时间部门开发一个新的项目，用的dubbo+spring boot架构，日志平台用的elk，不过在项目真正跑起来的之后发现，只有一个应用可以正常推送日志，其他应用的日志在elk中一个也看不到。我最终排查解决了这个问题，并且记录下来。

一开始这个问题很让人摸不着头脑，因为日志推送是一个单独的maven模块，其他所有的应用都引用这个模块，可是却只有一个应用是可以正常推送的，而且这个日志推送模块是在一套生产中运行的项目中copy过来的，按理是不应该会有不可用的现象。

最开始怀疑日志消息在kafka中断掉了，于是登上服务器的kafka中检查了一下，kafka中并没有消息积累，而且尝试在本地运行应用，kafka中也并没有接收到任何消息。

那么问题肯定就出在logback上面了，说到这里先介绍一下logback的几个关键点 Logger、Appender和Layout

• Logger

  日志的记录器，主要负责记录存放日志对象

• Appender

  负责指定日志的输出地，可以是控制台、文件或者远程消息队列等。这个项目就是使用一个KafkaAppender讲日志推送到Kafka

• Layout

  负责日志格式化输出

 

因为日志输出到控制台是没有问题的，所以问题应该出在KafkaAppender上，在logback.xml中开启logback内部的日志信息，查看一下是否有报错。

<!--将debug属性改为true，即可开启logback内部日志，其他几个属性值的含义自行百度-->
<configuration debug="false" scan="false" scanPeriod="10 seconds">
</configuration>

这一改不要紧，运行起没有正常推送日志的应用，控制台立即打印出了错误信息(下图是我模拟的一个错误信息)。

根据异常定位到了错误代码，这是Layout的一个Coverter类，对日志进行格式化输出。到这里其实有点疑惑，因为正常的那个应用在这里是没有任何异常的。

跟踪一下代码getMDCPropertyMap()，ILoggerEvent是logback的日志事件接口，在我的项目中真正实现类ch.qos.logback.classic.spi.LoggingEvent#getMDCPropertyMap

public Map<String, String> getMDCPropertyMap() {
        // populate mdcPropertyMap if null
        if (mdcPropertyMap == null) {
            MDCAdapter mdc = MDC.getMDCAdapter();
            if (mdc instanceof LogbackMDCAdapter)
                mdcPropertyMap = ((LogbackMDCAdapter) mdc).getPropertyMap();
            else
                mdcPropertyMap = mdc.getCopyOfContextMap();
        }
        // mdcPropertyMap still null, use emptyMap()
        if (mdcPropertyMap == null)
            mdcPropertyMap = Collections.emptyMap();

        return mdcPropertyMap;
    }

看到这段代码就发现了问题的关键了，java.utils.Collections.emptyMap()返回的Map是一个不支持添加删除的空Map，所以报错地方可以理解了，说道这里要介绍一下MDC这个东西。

MDC是一个用在多线程下记录线程上下文的一些属性信息的一个类，底层是用ThreadLocal实现的。
比如某个用户请求执行一个操作，这个操作全部是在同一个用户线程下执行的，所有可以在请求入口的地方在MDC中设置用户的一些信息，然后再打印日志的时候就可以顺便附带上不同用户的信息。
日志的链路追踪也可以通过这种方式来实现。

所以问题就是在这个事件产生之前MDC中是没有设置任何属性的。了解了这个问题，又出现了一个新的问题，我们当前这个系统是有设置MDC的，我们这套dubbo的rpc系统使用的zipkin做链路追踪，所以在web入口使用Filter设置Trace和其他相应的属性，然后再dubbo的consumer方和provider方都使用了Filter设置相应的Trace属性。所有MDC中肯定是有值的，而且关键一点就是有个应用是可以正常推送日志的。问题到这里又让人很头疼了，暂时也没什么线索了。

最后还是我在查看MDC的时候发现了问题所在，logback中的MDC使用的是slf4j中的MDC，而Filter设置Trace的时候用的是log4j的MDC。在这里介绍一下slf4j。

slf4j全名为simple logging Facade for java，也就是简单日志门面，
如其名一样，slf4j提供了日志的接口，而日志的实现则由其他日志包来提供，
通过over包来做桥接。

如上文所说两处的MDC并不相同，所以导致了在ILoggerEvent中获取MDC中的值时是空，然而还是前面说的问题，为什么有个应用是正常使用的呢，而且这套日志模块是从一个正常使用的系统上面copy下来，如果这个地方有问题的话，所有模块都不能正常使用才对啊。

我再次研究了一下MDC，发现了另外一个问题：

org.apache.log4j.MDC 这个类在log4j下和在 log4j-over-slf4j下都有，不仅同名，还同包名。对比了一下两处的MDC，终于发现了最本质的问题之一，log4j-over-slf4j下的org.apache.log4j.MDC底层用的slf4j的MDC来实现的，而在日志模块里面确实用的是log4j下的org.apache.log4j.MDC。此处介绍一下java的类加载顺序。

虚拟机对于同包同名的类加载时按照引用顺序来加载的，只会加载第一个出现的类，后续的都不会再加载。

所以在可以正常推送日志的模块里面引入了其他的log4j-over-slf4j早于引入这个日志模块，该类可以正常使用。而我前面说的日志模块是在一个正常的系统中copy过来的，为什么那个系统是正常运行的呢，经我后续的验证，如我猜测一样确实只是运气而已，刚好也有log4j-over-slf4j早于log4j的引用。

把代码中所有用到MDC的地方全部改为slf4j下的MDC，前面的问题迎刃而解。

 

 

此次问题排除主要有两个知识点

• slf4j 日志门面
• java的类加载顺序