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
·
今天无意中发现线上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}
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=106return 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 bindingStaticLoggerBinder.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 iterationSet 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依赖去掉就好了。
更多推荐
已为社区贡献1条内容
所有评论(0)