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

最新推荐文章于 2024-08-30 14:59:46 发布

qbw2010

最新推荐文章于 2024-08-30 14:59:46 发布

阅读量1.5w

点赞数

分类专栏： java 文章标签： zookeeper 日志 slf4j log4j

java 专栏收录该内容

44 篇文章 0 订阅

订阅专栏

今天无意中发现线上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依赖去掉就好了。