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

权威|前沿|技术|干货|国内首个API全生命周期开发者社区

更多推荐