Log4j日志记录水平调整 -

gdfloyd

浏览: 74033 次
性别:
来自: 广州

最近访客更多访客>>

z2042489

liujickson

llhhsspp08

小菜鸡也想飞

博主相关

博客

微博

相册

留言

关于我

文章分类

全部博客 (13)

社区版块

存档分类

Log4j日志记录水平调整

Log4j 日志记录水平

最近研究了一下Log4j这个被广发使用的日志组件，缘于三个问题：日志水平调整问题，日志运行时配置修改和日志模块化问题。Log4j不是一天两天的了，相信早就会有相应的解决方法。

先来看第一个问题。生产运行中考虑到日常资源消耗和运行性能是不宜开启低水平日志记录的。然而，一旦生产运行环境出现异常，没有相当详细程度的日志信息的话，要进行快速的定位分析准确的排查判断几乎是不可能的。这个矛盾令人十分纠结，是应该提高日志水平减少不必要的日志输出消耗呢，降低日志水平还是管它有理无理尽量详细记录呢。我的想法是两者都要兼顾，如果要做一个折衷的话，日志组件能够根据运行的记录水平，对日志内容进行细粒度输出控制。

一种解决思路是自定义PatternLayout能够根据当前的日志记录水平来进行不同格式的日志输出。可以在Log4j配置中划定高水平和低水平的日志界限（Threshold），低水平记录（对应于警告及其以下）和高水平记录（对应于错误及其以上）分别采用详细的日志格式和粗略的日志格式。我的扩展实现如下，像所在文件和所在行数等信息，要获取这些信息需要通过运行时反射得到，对日志性能影响甚大，因而，凡是警告及其以下低级别的日志不予输出，而对于错误及其以上高级别的日志则记录。

public class LogLevelThresholdPatternLayout extends Layout {

	private Level threshold =  Level.WARN;
	
	private static final String DEFAULT_LOW_LEVEL_PATTERN = "%d{yyyy-MM-dd HH:mm:ss,SSS} [%-5p] %m%n";
	private static final String DEFAULT_HIGH_LEVEL_PATTERN = "%d{yyyy-MM-dd HH:mm:ss,SSS} [%-5p] %t %l %m%n";
	
	private PatternLayout lowLevelPatternLayout;
	private PatternLayout highLevelPatternLayout;	

	public void setThreshold(Level threshold) {
		this.threshold = threshold;
	}
	
	public void setLowLevelConversionPattern(String lowLevelConversionPattern){
		
		lowLevelPatternLayout = new PatternLayout(lowLevelConversionPattern);
	}
	
	public void setHighLevelConversionPattern(String highLevelConversionPattern){
		
		highLevelPatternLayout = new PatternLayout(highLevelConversionPattern);
	}
	
	@Override
	public void activateOptions() {
		if (lowLevelPatternLayout == null) {
			lowLevelPatternLayout = new PatternLayout(DEFAULT_LOW_LEVEL_PATTERN);
		}
		lowLevelPatternLayout.activateOptions();
		if (highLevelPatternLayout == null) {
			highLevelPatternLayout = new PatternLayout(DEFAULT_HIGH_LEVEL_PATTERN);
		}
		highLevelPatternLayout.activateOptions();
	}

	@Override
	public String format(LoggingEvent event) {
		
		if (threshold.isGreaterOrEqual(event.getLevel())) {
			return lowLevelPatternLayout.format(event);
		} else {
			return highLevelPatternLayout.format(event);
		}
	}

	@Override
	public boolean ignoresThrowable() {
		return true;
	}
}

这时候 Log4j的XML配置就像如下便可：

<appender name="RollingLogFile" class="org.apache.log4j.DailyRollingFileAppender">
	    <param name="File" value="test.log" />
	    <layout class="xxx.yyy.zzz.LogLevelThresholdPatternLayout">
	      <param name="highLevelConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss,SSS} [%-5p] %t %l %m%n" />
	      <param name="lowLevelConversionPattern" value="%d{HH:mm:ss} [%-5p] %m%n" />
	    </layout>
</appender>

在查看Log4j的Javadoc进行配置的时候发现了另外一个问题。Log4j在版本1.2.16引入了一个新的类org.apache.log4j.EnhancedPatternLayout来替代原有使用的org.apache.log4j.PatternLayout。如果条件允许，特别是在新的部署环境应该优先使用。于是，上面的配置因此可以改成如下这样：

public class LogLevelThresholdPatternLayout extends Layout {

	private Level threshold =  Level.WARN;
	private EnhancedPatternLayout lowLevelPatternLayout;
	private EnhancedPatternLayout highLevelPatternLayout;	

	public void setThreshold(Level threshold) {
		this.threshold = threshold;
	}
	
	public void setLowLevelConversionPattern(String lowLevelConversionPattern){
		
		lowLevelPatternLayout = new EnhancedPatternLayout(lowLevelConversionPattern);
	}
	
	public void setHighLevelConversionPattern(String highLevelConversionPattern){
		
		highLevelPatternLayout = new EnhancedPatternLayout(highLevelConversionPattern);
	}
	...
        ...
}

除此之外，旧版本的的org.apache.log4j.DailyRollingFileAppender同org.apache.log4j.PatternLayout一样，应该优先使用org.apache.log4j.rolling.RollingFileAppender作为替代，这个可以从Apache Logging另外一个子项目apache-log4j-extra找到的。于是去下载log4j-extra来玩一下，刚好发现log4j-extra最近有了更新。apache-log4j-extra基于Log4j1.2版本，其大部分源码源于已经停止继续维护的Log4j-1.3版本。同原有的org.apache.log4j.DailyRollingFileAppender相比，配置上的主要区别是专门分出出一个的org.apache.log4j.rolling.TimeBasedRollingPolicy的类来对文件滚动细节进行具体控制。配置如下：

<appender name="RollingLogFile" class="org.apache.log4j.rolling.RollingFileAppender">
	<rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
	  <param name="ActiveFileName" value="test.log" />
	  <param name="FileNamePattern" value="test.log.%d{yyyy-MM-dd}" />
	</rollingPolicy>
	...
        ...
</appender>

回到最初的日志水平调整问题，另外一种解决思路可以通过配置Logger的多个Appender，每个Appender再配置相应的Layout来实现。为了避免多个Appender重复记录，还需要配置对应的Filter和Threshold来过滤相应的日志水平。这种方式会导致配置有点繁琐，但好处是仅通过对Log4j的进行适当配置便可，无需额外扩展代码实现。具体下面的配置如下。

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

<appender name="HIGHLOG" class="org.apache.log4j.DailyRollingFileAppender">
	<param name="File" value="test.log" />
	<layout class="org.apache.log4j.PatternLayout">
	    <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss,SSS} [%-5p] %m%n" />
	 </layout>
	 <filter class="org.apache.log4j.varia.LevelRangeFilter">
	      <param name="LevelMin" value="INFO" />
	 </filter>
       </appender>
	
       <appender name="LOWLOG" class="org.apache.log4j.DailyRollingFileAppender">
	    <param name="Threshold" value="WARN"/>
	    <param name="File" value="test.log" />
	    <layout class="org.apache.log4j.PatternLayout">
	      <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss,SSS} [%-5p] %t %l %m%n" />
	    </layout>
	</appender>
	
	<logger name="xxx.yyy.zzz">
		<appender-ref ref="HIGHLOG" />
                <appender-ref ref="LOWLOG" />
	</logger>

</log4j:configuration>

像上面的配置经过简单试验，是可以达到同上一种方式PatternLayout自定义扩展一样的效果的。然而，这样配置存在一个隐患，在文件滚动的时候多个FileAppender包装下对同一个文件的，能否做到滚动在Appender之间做到同步，能否不会因I/O异常而出现死锁等等是很值得怀疑的，特别是文件发生滚动时又发生大量日志输出的时候，会不会导致整个系统长时间停顿等等。具体的触发机制很难深究，我又没做过实际试验研究不好妄下结论。默认设置下的每日滚动，是发生在每日凌晨这个时间点。这时候一般是业务空闲时期，相信实际中也很难触发文件同步或者数据丢失问题。为了保险起见应该使用由log4j-extra提供的org.apache.log4j.rolling.RollingFileAppender。按照Javadoc的说法，应该是修复了先前的DailyRollingFileAppender表现出的数据同步和丢失问题。

下面来看第二个问题日志配置运行时修改。为了观察系统运行状态，捕捉和监控系统缺陷源头，往往需要对记录水平等等日志配置项进行运行时调整，而最重要的前提是系统服务不能停止。Log4j提供两种方式来解决。第一种就是定期重新加载Log4j配置文件。这种方式使用很简单，加载时候调用如下方法之一，并指定文件重新加载间隔便可。

DOMConfigurator.configureAndWatch(String configFilename, long delay)

PropertyConfigurator.configureAndWatch(configFilename, delay)

个人不很推荐这种方式，把所有配置重新加载一次，Log4j内部会不会对Logger/Appender进行一定的同步处理，会不会做成大范围的系统停顿要打个问号，特别在日志输出很频繁的情况下。很多时候，我们往往只需要运行时调整一下日志记录水平参数，没必要像第一种那样将配置全部重新Load一次，第二种方式JMX就排上用场了。Log4j是内置JMX的支持，对于这个问题是有很好的解决的。只需要把相应的Log4j对象包装到MBean中去并注册到MBean服务器中去便可通过相应MBean管理环境来进行日志记录水平运行时调整。具体实现可以参考由Log4j提供的如下类：

org.apache.log4j.jmx.HierarchyDynamicMBean

org.apache.log4j.jmx.AppenderDynamicMBean

org.apache.log4j.jmx.LoggerDynamicMBean

org.apache.log4j.jmx.LayoutDynamicMBean

向mbean服务器注册Logger可以是类似如下的大致上可以像如下的实现。

        MBeanServer mbeansServer = MBeanServerFactory.createMBeanServer();
	LoggerRepository hierarchy = LogManager.getLoggerRepository();
	Enumeration<?> loggerEnumeration = hierarchy.getCurrentLoggers();
	while (loggerEnumeration.hasMoreElements()) {
		Logger logger = (Logger)loggerEnumeration.nextElement();
		LoggerDynamicMBean loggerDynamicMBean = 
			new LoggerDynamicMBean(logger);
		try {
			mbeansServer.registerMBean(loggerDynamicMBean, 
					createObjectName("logger", logger.getName()));
		} catch (InstanceAlreadyExistsException e) {
			// TODO output log ?
		} catch (MBeanRegistrationException e) {
			// TODO output log ?
		} catch (NotCompliantMBeanException e) {
			// TODO output log ?
		}
	}

private ObjectName createObjectName(String typeName, String objName) {
		ObjectName objectName = null;
		try {
			objectName =new ObjectName(
					"org.apache.log4j.default:type=" + typeName + ",name=" + objName);
		} catch (MalformedObjectNameException e) {
			// TODO output log ?
		} catch (NullPointerException e) {
			// TODO output log ?
		}
		return objectName;
	}

下面开始要说的是日志模块化的问题。分别准备两个Log4j配置文件log4j-1.xml 和log4j-2.xml，并分别加载运行，测试代码可以像如下的代码。

URL url1 = 
		Thread.currentThread()
			.getContextClassLoader()
			.getResource("xxx/yyy/log4j/log4j-1.xml");
	Logger logger = LogManager.getLogger("xxx.yyy.zzz");
	DOMConfigurator.configure(url1);	
	logger.info("test log 1 here");
	
	URL url2 = 
		Thread.currentThread()
			.getContextClassLoader()
			.getResource("xxx/yyy/zzz/log4j/log4j-2.xml");		
	DOMConfigurator.configure(url1);	
	logger.info("test log 2 here");

运行后会发现后面加载的Log4j-2.xml的配置会覆盖前面的Log4j-1.xml的配置，如果有相同名字的Logger或者Appender的话。如果均使用默认类路径下的配置文件(log4j.xml/log4j.properties)或者同一个配置文件的话，又或者Logger和Appender没有重名的话，就不会存在这样的问题。但是，在应用程序多模块环境下，是很容易发生日志配置文件冲突的，这时候就需要一定的隔离机制。Log4j内部的org.apache.log4j.Hierarchy管理不同的Logger就是通过这样的完全限定名来管理Logger配置的层级继承关系的。因而，绝大部分情况下模块可以根据包名来唯一区分，最简单最直接的隔离就是在定义名称的时候用包名来限定，这样就不会被其他模块干扰到。

<appender name="xxx.yyy.zzz.STDOUT" class="org.apache.log4j.ConsoleAppender">
	    <layout class="org.apache.log4j.PatternLayout">
	      <param name="ConversionPattern"
	        value="%d{yyyy-MM-dd HH:mm:ss} [Log-1] [%-5p] [%c{1}] %m%n" />
	    </layout>
  	</appender>
	
	<logger name="xxx.yyy.zzz">
    	<appender-ref ref="xxx.yyy.zzz.STDOUT" />
  	</logger>

还有一种思路是对Log4j进行适当扩展。Log4j使用org.apache.log4j.spi.LoggerRepository来维护管理不同的Logger状态。可以用不同的LoggerRepository来划分模块的界限。org.apache.log4j.spi.LoggerRepository的具体实现就是org.apache.log4j.Hierarchy。当用户代码调用LogManager#getLogger的时候，就会通过LogManager#getLoggerRepository来返回一个默认的Hierarchy类实例。默认的Hierarchy实例在LogManager静态初始化块中中实例化，Hierarchy内部维护一个用来存储Logger的Hashtable，返回给上层的LogManager#getLogger的调用。LogManager提供一个方法setRepositorySelector来设定选择器，可以用来改变调用getLoggerRepository时所返回的默认Hiearchy实例。实现自己的RepositorySelector可能类似如下。

public class MultipleModulesRepositorySelector extends DefaultRepositorySelector {
		
		private static final Map<String, LoggerRepository> repositories = 
			Collections.synchronizedMap(new HashMap<String, LoggerRepository>()); 
		
		public MultipleModulesRepositorySelector(LoggerRepository defaultRepository) {
			super(defaultRepository);
		}
	
		@Override
		public LoggerRepository getLoggerRepository() {
			
			LoggerRepository loggerRepository = repositories.get(getModuleName());
			if (loggerRepository != null) {
				return loggerRepository;
			} else {
				// not found and create a new LoggerRepository
				LoggerRepository hierarchy = new Hierarchy(new RootLogger((Level) Level.DEBUG));
				repositories.put(moduleName, hierarchy);
				return hierarchy;
			}
			
			// returns the default repository
			return super.getLoggerRepository();
		}
		
		protected String getModuleName() {
			// detail implementation here
			// ...
		}
	}
	
	// 用户扩展代码如下，静态初始化RepositorySelector。
	
	static {
	
		LoggerRepository defaultLoggerRepository = LogManager.getLoggerRepository();
		MultipleModulesRepositorySelector selector = 
			new MultipleModulesRepositorySelector(defaultLoggerRepository);
		LogManager.setRepositorySelector(
			RepositorySelector selector, new Object()); // only can be invoked once
	}

这种实现实际上不甚理想，Logger实例如果是作为类的静态成员变量就有可能仅仅从默认的LoggerRepository中生成并获取，而非从对应模块的LoggerRepository中拿到。这种实现必须要求Logger只能是类普通的非静态成员变量。还是老老实实采用完全限定名来避免冲突。最后不得不提一下Logback，一个由Log4j原作者所推出新的日志组件对此日志模块化的解决方案。

在Logback中，可以通过设置每个配置文件的上下文名称(contextName)来划定模块界限。其配置是类似这样的：

<configuration>
	
	  <contextName>myAppName</contextName>
	  
	  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
	    <encoder>
	      <pattern>%d %contextName [%t] %level - %msg%n</pattern>
	    </encoder>
	  </appender>
	
	  <root level="DEBUG">
	    <appender-ref ref="STDOUT" />
	  </root>
	</configuration>

再在一个总的配置文件中分别导入各子模块的配置，而用户代码只需要导入一个总入口文件便可。

<configuration>
	  <include file="xxx/yyy/zzz/configuration/module1.xml"/>
	  <include file="xxx/yyy/zzz/configuration/module2.xml"/>
	  ...
	</configuration>

除此之外，对于运行在JavaEE容器的多应用，Logback还可以根据应用初始化上下文来指定上下文名称来达到隔离目的。

	<configuration>
		<insertFromJNDI env-entry-name="java:comp/env/appName" as="appName" />
  		<contextName>${appName}</contextName>
		...
	</configuration>

最好结尾跟Logback宣传一下，一些不被Log4j直接支持的新特性

自动清除日志滚动的历史存档
配置更灵活，如与Ant配置类似的子文件引入，变量替代，配置文件条件动态化
根据运行时属性切换目标输出文件，如某种特定的访问记录到单独的文件
打印异常堆栈所在包

分享到：

Logback 日志隔离－把日志输出到不同目标 | Trac安装过程记录

2013-11-05 23:50
浏览 7152
评论(0)
分类:开源软件
查看更多

发表评论

您还没有登录,请您登录后再发表评论

最近访客更多访客>>

博主相关

文章分类

社区版块

存档分类

最新评论

Log4j日志记录水平调整

评论

发表评论

相关推荐

最近访客 更多访客>>

博主相关

文章分类

社区版块

存档分类

最新评论

Log4j日志记录水平调整

评论

发表评论

相关推荐

最近访客更多访客>>