zookeeper输出大量debug日志原因分析

今天无意中发现线上tomcat的catalina.out文件输出大量的zookeeper debug信息，以下是日志片段：10:30:03.973 [localhost-startStop-1-SendThread(10.168.180.94:2181)] DEBUG org.apache.zookeeper.ClientCnxn – Reading reply sessionid:0x2

qbw2010

15838人浏览 · 2017-06-02 09:43:03

qbw2010 · 2017-06-02 09:43:03 发布

今天无意中发现线上tomcat的catalina.out文件输出大量的zookeeper debug信息，以下是日志片段：

10:30:03.973 [localhost-startStop-1-SendThread(10.168.180.94:2181)] DEBUG org.apache.zookeeper.ClientCnxn – Reading reply sessionid:0x2497977a96e368f, packet:: clientPath:null serverPath:null finished:false header:: 2054411,4 replyHeader:: 2054411,30431451472,0 request:: ‘/cache-redis/cluster-cache-kop/monitors/redis-10.168.163.13-6379/monitor-5063e8eb-2c44-4560-8f32-821d9da0928e,F response:: #7b226865616c7468223a36383539347d,s{30421042529,30431451467,1437462953967,1437532203953,68595,0,0,164796416226375311,16,0,30421042529}
10:30:03.974 [localhost-startStop-1-SendThread(10.168.180.94:2181)] DEBUG org.apache.zookeeper.ClientCnxn – Reading reply sessionid:0x2497977a96e368f, packet:: clientPath:null serverPath:null finished:false header:: 2054412,4 replyHeader:: 2054412,30431451472,0 request:: ‘/cache-redis/cluster-cache-kop/monitors/redis-10.168.163.13-6379/monitor-fd44c3c8-49ed-4493-9fb3-15c5e9b32b48,F response:: #7b226865616c7468223a36363534397d,s{30421293932,30431451332,1437465020671,1437532203056,66550,0,0,164796416226375313,16,0,30421293932}
10:30:03.974 [localhost-startStop-1-SendThread(10.168.180.94:2181)] DEBUG org.apache.zookeeper.ClientCnxn – Reading reply sessionid:0x2497977a96e368f, packet:: clientPath:null serverPath:null finished:false header:: 2054413,4 replyHeader:: 2054413,30431451472,0 request:: ‘/cache-redis/cluster-cache-kop/monitors/redis-10.168.163.13-6379/monitor-a0485714-92a8-4ec8-b1cf-eb52f134f53c,F response:: #7b226865616c7468223a3438383434327d,s{30369309074,30431451356,1437030682965,1437532203246,488443,0,0,236854010264761444,17,0,30369309074}
10:30:03.974 [localhost-startStop-1-SendThread(10.168.180.94:2181)] DEBUG org.apache.zookeeper.ClientCnxn – Reading reply sessionid:0x2497977a96e368f, packet:: clientPath:null serverPath:null finished:false header:: 2054414,4 replyHeader:: 2054414,30431451472,0 request:: ‘/cache-redis/cluster-cache-kop/monitors/redis-10.168.163.13-6379/monitor-6cbc3490-d818-4f87-9528-9caa948f1595,F response:: #7b226865616c7468223a3438383330307d,s{30369305395,30431451394,1437030658897,1437532203574,488301,0,0,164796416226375097,17,0,30369305395}

这些基本都是zookeeper输出的，而我们的log4j文件配置的root logger都是info级别的，初步看root logger貌似没有生效，我特的配置了一个这样的logger，也没有生效，如下：

  <logger name= “org.apache.zookeeper.ClientCnxn” additivity=“false”>

               <level value= “INFO” />

               <appender-ref ref= “console_appender” />

        </logger>

日志基本都是org.apache.zookeeper.ClientCnxn输出的，看了ClientCnxn的源码，zookeeper 3.3.3里的ClientCnxn的log直接用log4j，zookeeper 3.4.3里的ClientCnxn用的是slf4j，如下：

public class ClientCnxn {

private static final Logger LOG = LoggerFactory.getLogger(ClientCnxn.class);

这里的LoggerFactory是org.slf4j.LoggerFactory。slf4j和log4j什么关系呢？日志家族关系如下：

　通过上面的图，可以简单的理清关系！commons-logging和slf4j都是日志的接口，供用户使用，而没有提供实现！log4j,logback等等才是日志的真正实现。当我们调用接口时，接口的工厂会自动寻找恰当的实现，返回一个实现的实例给我服务。这些过程都是透明化的，用户不需要进行任何操作。那么，在这个应用里，slf4j到底用的是哪种实现呢？log4j配置貌似没有生效。于是我就顺着源码看了下去。

public static Logger getLogger(String name) {

ILoggerFactory iLoggerFactory = getILoggerFactory();

return iLoggerFactory.getLogger(name);

}

slf4j是一种日志接口，不是具体日志实现，具体日志实现通过ILoggerFactory iLoggerFactory = getILoggerFactory()得到。再看getILoggerFactory()方法内容，如下：

  public static ILoggerFactory getILoggerFactory() {

    if (INITIALIZATION_STATE == UNINITIALIZED) {

      INITIALIZATION_STATE = ONGOING_INITIALIZATION;

      performInitialization();

    }

    switch (INITIALIZATION_STATE) {

      case SUCCESSFUL_INITIALIZATION:

        return StaticLoggerBinder.getSingleton().getLoggerFactory();

      case NOP_FALLBACK_INITIALIZATION:

        return NOP_FALLBACK_FACTORY;

      case FAILED_INITIALIZATION:

        throw new IllegalStateException( UNSUCCESSFUL_INIT_MSG);

      case ONGOING_INITIALIZATION:

        // support re-entrant behavior.

        // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106

        return TEMP_FACTORY;

    }

    throw new IllegalStateException( “Unreachable code”);

}

这段代码

  if ( INITIALIZATION_STATE == UNINITIALIZED) {

      INITIALIZATION_STATE = ONGOING_INITIALIZATION ;

      performInitialization();

    }

表示如果状态是还未初始化，则初始化，初始化代码在performInitialization()方法里，该方法如下：

private final static void performInitialization () {

    bind ();

    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {

      versionSanityCheck();

    }

}

再看bind方法，内幕尽在这个方法里：

  private final static void bind () {

    try {

      Set staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();

      reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);

      // the next line does the binding

      StaticLoggerBinder.getSingleton();

      INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;

      reportActualBinding(staticLoggerBinderPathSet);

      emitSubstituteLoggerWarning();

    } catch (NoClassDefFoundError ncde) {

      String msg = ncde.getMessage();

      if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {

        INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;

        Util.report(“Failed to load class \”org.slf4j.impl.StaticLoggerBinder\”.”);

        Util.report(“Defaulting to no-operation (NOP) logger implementation”);

        Util.report(“See “ + NO_STATICLOGGERBINDER_URL

                + ” for further details.”);

      } else {

        failedBinding(ncde);

        throw ncde;

      }

    } catch (java.lang.NoSuchMethodError nsme) {

      String msg = nsme.getMessage();

      if (msg != null && msg.indexOf(“org.slf4j.impl.StaticLoggerBinder.getSingleton()” ) != -1) {

        INITIALIZATION_STATE = FAILED_INITIALIZATION;

        Util.report(“slf4j-api 1.6.x (or later) is incompatible with this binding.”);

        Util.report(“Your binding is version 1.5.5 or earlier.”);

        Util.report(“Upgrade your binding to version 1.6.x.” );

      }

      throw nsme;

    } catch (Exception e) {

      failedBinding(e);

      throw new IllegalStateException( “Unexpected initialization failure”, e);

    }

}

首先通过findPossibleStaticLoggerBinderPathSet方法找到可能的log实现，原理就是在classpath里搜索org.slf4j.impl.StaticLoggerBinder.class,将该class的所有路径都找出来，放到一个set里。代码如下：

  private static String STATIC_LOGGER_BINDER_PATH = “org/slf4j/impl/StaticLoggerBinder.class” ;

  private static Set findPossibleStaticLoggerBinderPathSet () {

    // use Set instead of list in order to deal with bug #138

    // LinkedHashSet appropriate here because it preserves insertion order during iteration

    Set staticLoggerBinderPathSet = new LinkedHashSet();

    try {

      ClassLoader loggerFactoryClassLoader = LoggerFactory. class

              .getClassLoader();

      Enumeration paths;

      if (loggerFactoryClassLoader == null) {

        paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);

      } else {

        paths = loggerFactoryClassLoader

                .getResources( STATIC_LOGGER_BINDER_PATH);

      }

      while (paths.hasMoreElements()) {

        URL path = (URL) paths.nextElement();

        staticLoggerBinderPathSet.add(path);

      }

    } catch (IOException ioe) {

      Util.report(“Error getting resources from path” , ioe);

    }

    return staticLoggerBinderPathSet;

}

reportMultipleBindingAmbiguity(staticLoggerBinderPathSet)做的事情是这样的：如果发现有多个log实现，则将它们的路径都打印出来，提醒开发者，代码如下：

  private static void reportMultipleBindingAmbiguity (Set staticLoggerBinderPathSet) {

    if (isAmbiguousStaticLoggerBinderPathSet(staticLoggerBinderPathSet)) {

      Util.report(“Class path contains multiple SLF4J bindings.”);

      Iterator iterator = staticLoggerBinderPathSet.iterator();

      while (iterator.hasNext()) {

        URL path = (URL) iterator.next();

        Util.report(“Found binding in [“ + path + “]” );

      }

      Util.report(“See “ + MULTIPLE_BINDINGS_URL + ” for an explanation.”);

    }

}

StaticLoggerBinder.getSingleton()这一句很巧妙很隐晦，因为org.slf4j.StaticLoggerBinder这个类在classpath里可能会有多个，但是日志系统肯定只会用到一个，那么到底是哪一个呢？其实StaticLoggerBinder. getSingleton()会导致classloader将org.slf4j.StaticLoggerBinder加载到内存里，至于StaticLoggerBinder到底是哪个包下面的，就不好说了。logback里有org.slf4j.StaticLoggerBinder,log4j里也有org.slf4j.StaticLoggerBinder。这一点需要注意，slf4j虽然是一种日志接口，但是它不是通过真的约定一个interface让各个日志系统去实现这个接口，而是每个日志实现里必须要有这个org.slf4j.StaticLoggerBinder，然后slf4j通过加载org.slf4j.StaticLoggerBinder这个class，找到一个日志实现，反正肯定能找到一个，当应用里引入了多个日志实现时，用哪个就不好说了，

最后的解决方法很简单，将pom里的logback依赖去掉就好了。