程序中记录日志

程序中记录日志一般有两个目的：Troubleshooting和显示程序运行状态。好的日志记录方式可以提供我们足够多定位问题的依据。日志记录大家都会认为简单，但如何通过日志可以高效定位问题并不是简单的事情。这里列举下面三个方面的内容，辅以代码示例，总结如何写好日志，希望对他人有所启发和帮助：

怎样记日志可以方便Troubleshooting

程序运行状态可以记哪些

应该避免怎样的日志方式

怎样记日志可以方便Troubleshooting？

1. 对外部的调用封装

程序中对外部系统与模块的依赖调用前后都记下日志，方便接口调试。出问题时也可以很快理清是哪块的问题

1.  LOG.debug("Calling external system:" + parameters);  2.  Object result = null;  3.  try {  4.      result = callRemoteSystem(params);  5.      LOG.debug("Called successfully. result is " + result);  6.  } catch (Exception e) {  7.      LOG.warn("Failed at calling xxx system . exception : " + e);  8.  }  

2.状态变化

程序中重要的状态信息的变化应该记录下来，方便查问题时还原现场，推断程序运行过程

1.  boolean isRunning;  2.    3.  isRunning = true;  4.  LOG.info("System is running");  5.    6.  //...  7.    8.  isRunning = false;  9.  LOG.info("System was interrupted by " + Thread.currentThread().getName());  

3.系统入口与出口：

这个粒度可以是重要方法级或模块级。记录它的输入与输出，方便定位

1.  void execute(Object input) {  2.      LOG.debug("Invoke parames : " + input);  3.      Object result = null;  4.        5.      //business logic6.        7.      LOG.debug("Method result : " + result);  8.  }  

4.业务异常：

任何业务异常都应该记下来：

1.  try {  2.      //business logical  3.  } catch (IOException e) {  4.      LOG.warn("Description xxx" , e);  5.  } catch (BusinessException e) {  6.      LOG.warn("Let me know anything");  7.  } catch (Exception e) {  8.      LOG.error("Description xxx", e);  9.  }  10.   

5.非预期执行：

为程序在“有可能”执行到的地方打印日志。如果我想删除一个文件，结果返回成功。但事实上，那个文件在你想删除之前就不存在了。最终结果是一致的，但程序得让我们知道这种情况，要查清为什么文件在删除之前就已经不存在

1.  int myValue = xxxx;  2.  int absResult = Math.abs(myValue);  3.  if (absResult < 0) {  4.      LOG.info("Original int " + myValue + "has nagetive abs " + absResult);  5.  }  

6.很少出现的else情况：

else可能吞掉你的请求，或是赋予难以理解的最终结果

1.  Object result = null;  2.  if (running) {  3.     result = xxx;  4.  } else {  5.     result = yyy;  6.     LOG.debug("System does not running, we change the final result");  7.  }  

程序运行状态可以记哪些？

程序在运行时就像一个机器人，我们可以从它的日志看出它正在做什么，是不是按预期的设计在做，所以这些正常的运行状态是要有的。

1. 程序运行时间：

1.  long startTime = System.currentTime();  2.    3.  // business logical  4.    5.  LOG.info("execution cost : " + (System.currentTime() - startTime) + "ms");　  

2. 大批量数据的执行进度：

 1.  LOG.debug("current progress: " + (currentPos * 100 / totalAmount) + "%");  

3.关键变量及正在做哪些重要的事情：

执行关键的逻辑，做IO操作等等

1.  String getJVMPid() {  2.     String pid = "";  3.     // Obtains JVM process ID  4.     LOG.info("JVM pid is " + pid);  5.     return pid;  6.  }  7.    8.  void invokeRemoteMethod(Object params) {  9.      LOG.info("Calling remote method : " + params);  10.     //Calling remote server  11. }  

应该避免怎样的日志方式？

1. 混淆信息的Log

日志应该是清晰准确的: 当看到日志的时候，你知道是因为连接池取不到连接导致的问题么？

1.  Connection connection = ConnectionFactory.getConnection();  2.  if (connection == null) {  3.      LOG.warn("System initialized unsuccessfully");  4.  }  

2. 记错位置

产品代码中，使用console记录日志，导致没有找到日志。

     1. } catch (ConfigurationException e) {     2.    e.printStackTrace();     3. }

3. 记错级别

记错级别常常发生，常见的如：混淆代码错误和用户错误,如登录系统中，如果恶意登录，那系统内部会出现太多WARN，从而让管理员误以为是代码错误。可以反馈用户以错误，但是不要记录用户错误的行为，除非想达到控制的目的。

1.  LOG.warn("Failed to login by "+username+");

4. 遗漏信息

这里可能包含两种情况：（1）用户自己少写了信息,导致毫无参考价值；（2）用户调用log的方式导致丢失信息，如下例，没有stack trace.

     1.  } catch (Exception ex) {     2.   log.error(ex);     3.  }

总结：

日志记录在程序员日常编程实践中必须面对的事情，本文针对这个话题谈了下自己的体会，希望读者能有所收益。多有不足，请多包涵。

log4j输出多个自定义日志文件

如果在实际应用中需要输出独立的日志文件，怎样才能把所需的内容从原有日志中分离，形成单独的日志文件呢？

先看一个常见的log4j.properties文件，它是在控制台和test.log文件中记录日志：

复制代码 代码如下:

log4j.rootLogger=DEBUG, stdout, logfile 

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %m%n 

log4j.appender.logfile=org.apache.log4j.RollingFileAppender
log4j.appender.logfile.File=log/test.log
log4j.appender.logfile.MaxFileSize=128MB
log4j.appender.logfile.MaxBackupIndex=3
log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p [%t] %c.%M(%L) - %m%n

如果在同一类中需要输出多个日志文件呢？其实道理是一样的，先在Test.java中定义:

复制代码 代码如下:

private static Log logger1 = LogFactory.getLog("mylogger1");

private static Log logger2 = LogFactory.getLog("mylogger2");

log4j.properties中配置如下：

复制代码 代码如下:

log4j.logger.mylogger1=DEBUG,test1
log4j.appender.test1=org.apache.log4j.FileAppender
log4j.appender.test1.File=log/test1.log
log4j.appender.test1.layout=org.apache.log4j.PatternLayout
log4j.appender.test1.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p [%t] %c.%M(%L) - %m%n

log4j.logger.mylogger2=DEBUG,test2
log4j.appender.test2=org.apache.log4j.FileAppender
log4j.appender.test2.File=log/test2.log
log4j.appender.test2.layout=org.apache.log4j.PatternLayout
log4j.appender.test2.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p [%t] %c.%M(%L) - %m%n

不同日志要使用不同的logger(如输出到test1.log的要用logger1.info("abc"))。

还有一个问题，就是这些自定义的日志默认是同时输出到log4j.rootLogger所配置的日志中的，如何能只让它们输出到自己指定的日志中呢？别急，这里有个开关：

log4j.additivity. mylogger1 = false

它用来设置是否同时输出到log4j.rootLogger所配置的日志中，设为false就不会输出到其它地方了。

但是这种方式有个小缺陷，那就是打印的日志中类名只能是mylogger或者mylogger2。

2 动态配置路径
若程序需要的日志路径需要不断的变化，而又不可能每次都去改配置文件，此时可以利用环境变量来解决。

log4j的配置如下：

复制代码 代码如下:

log4j.rootLogger=DEBUG,INFOLOG,DEBUGLOG

#info log
log4j.appender.INFOLOG =org.apache.log4j.DailyRollingFileAppender
log4j.appender.INFOLOG.File= ${log.dir}/${log.info.file}
log4j.appender.INFOLOG.DatePattern=.yyyy-MM-dd
log4j.appender.INFOLOG.Threshold=INFO
log4j.appender.INFOLOG.layout=org.apache.log4j.PatternLayout
log4j.appender.INFOLOG.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p [%t] %c.%M(%L) - %m%n

#debug log
log4j.appender.DEBUGLOG =org.apache.log4j.RollingFileAppender
log4j.appender.DEBUGLOG.File= ${log.dir}/${log.debug.file}
log4j.appender.DEBUGLOG.Threshold=DEBUG
log4j.appender.DEBUGLOG.MaxFileSize=128MB
log4j.appender.DEBUGLOG.MaxBackupIndex=3
log4j.appender.DEBUGLOG.layout=org.apache.log4j.PatternLayout
log4j.appender.DEBUGLOG.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p [%t] %c.%M(%L) - %m%n

此时，在使用log打印日志之前，需要利用System定义日志的输出路径和文件名的环境变量：

复制代码 代码如下:

System.setProperty(“log.dir”, logDir);

System.setProperty(“log.info.file”, infoLogFileName);

System.setProperty(“log.debug.file”, debugLogFileName);

附：Pattern参数的格式含义

%c 输出日志信息所属的类的全名

%d 输出日志时间点的日期或时间，默认格式为ISO8601，也可以在其后指定格式，比如：%d{yyy-MM-dd HH:mm:ss }，输出类似：2013-8-19- 22：10：28

%f 输出日志信息所属的类的类名

%l 输出日志事件的发生位置，即输出日志信息的语句处于它所在的类的第几行

%m 输出代码中指定的信息，如log(message)中的message

%n 输出一个回车换行符，Windows平台为“/r/n”，Unix平台为“/n”

%p 输出优先级，即DEBUG，INFO，WARN，ERROR，FATAL。如果是调用debug()输出的，则为DEBUG，依此类推

%r 输出自应用启动到输出该日志信息所耗费的毫秒数

%t 输出产生该日志事件的线程名

很详细的Log4j配置步骤

. 配置文件 
Log4J配置文件的基本格式如下： 

复制代码 代码如下:

#配置根Logger
log4j.rootLogger = [ level ] , appenderName1 , appenderName2 , …
#配置日志信息输出目的地Appender
log4j.appender.appenderName = fully.qualified.name.of.appender.class
　　log4j.appender.appenderName.option1 = value1
　　…
　　log4j.appender.appenderName.optionN = valueN
#配置日志信息的格式（布局）
log4j.appender.appenderName.layout = fully.qualified.name.of.layout.class
　　log4j.appender.appenderName.layout.option1 = value1
　　…
　　log4j.appender.appenderName.layout.optionN = valueN

其中 [level] 是日志输出级别，共有5级：

复制代码 代码如下:

FATAL 0
ERROR 3
WARN 4
INFO 6
DEBUG 7

Appender 为日志输出目的地，Log4j提供的appender有以下几种： 

复制代码 代码如下:

org.apache.log4j.ConsoleAppender（控制台），
org.apache.log4j.FileAppender（文件），
org.apache.log4j.DailyRollingFileAppender（每天产生一个日志文件），
org.apache.log4j.RollingFileAppender（文件大小到达指定尺寸的时候产生一个新的文件），
org.apache.log4j.WriterAppender（将日志信息以流格式发送到任意指定的地方）
Layout：日志输出格式，Log4j提供的layout有以下几种：
org.apache.log4j.HTMLLayout（以HTML表格形式布局），
org.apache.log4j.PatternLayout（可以灵活地指定布局模式），
org.apache.log4j.SimpleLayout（包含日志信息的级别和信息字符串），
org.apache.log4j.TTCCLayout（包含日志产生的时间、线程、类别等等信息）

打印参数: Log4J采用类似C语言中的printf函数的打印格式格式化日志信息，如下:

复制代码 代码如下:

　 %m 输出代码中指定的消息
　　%p 输出优先级，即DEBUG，INFO，WARN，ERROR，FATAL
　　%r 输出自应用启动到输出该log信息耗费的毫秒数
　　%c 输出所属的类目，通常就是所在类的全名
　　%t 输出产生该日志事件的线程名
　　%n 输出一个回车换行符，Windows平台为“\r\n”，Unix平台为“\n”
　　%d 输出日志时间点的日期或时间，默认格式为ISO8601，也可以在其后指定格式，比如：%d{yyy MMM dd HH:mm:ss , SSS}，输出类似：2002年10月18日 22 ： 10 ： 28 ， 921
　　%l 输出日志事件的发生位置，包括类目名、发生的线程，以及在代码中的行数。举例：Testlog4.main(TestLog4.java: 10 )

2. 在代码中初始化Logger: 
1）在程序中调用BasicConfigurator.configure()方法：给根记录器增加一个ConsoleAppender，输出格式通过PatternLayout设为"%-4r [%t] %-5p %c %x - %m%n"，还有根记录器的默认级别是Level.DEBUG.
2）配置放在文件里，通过命令行参数传递文件名字，通过PropertyConfigurator.configure(args[x])解析并配置；
3）配置放在文件里，通过环境变量传递文件名等信息，利用log4j默认的初始化过程解析并配置；
4）配置放在文件里，通过应用服务器配置传递文件名等信息，利用一个特殊的servlet来完成配置。
3. 为不同的 Appender 设置日志输出级别：
当调试系统时，我们往往注意的只是异常级别的日志输出，但是通常所有级别的输出都是放在一个文件里的，如果日志输出的级别是BUG！？那就慢慢去找吧。
这时我们也许会想要是能把异常信息单独输出到一个文件里该多好啊。当然可以，Log4j已经提供了这样的功能，我们只需要在配置中修改Appender的Threshold 就能实现,比如下面的例子：
[配置文件] 

复制代码 代码如下:

### set log levels ###
log4j.rootLogger = debug , stdout , D , E
### 输出到控制台 ###
log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern = %d{ABSOLUTE} %5p %c{ 1 }:%L - %m%n
### 输出到日志文件 ###
log4j.appender.D = org.apache.log4j.DailyRollingFileAppender
log4j.appender.D.File = logs/log.log
log4j.appender.D.Append = true
log4j.appender.D.Threshold = DEBUG ## 输出DEBUG级别以上的日志
log4j.appender.D.layout = org.apache.log4j.PatternLayout
log4j.appender.D.layout.ConversionPattern = %-d{yyyy-MM-dd HH:mm:ss} [ %t:%r ] - [ %p ] %m%n
### 保存异常信息到单独文件 ###
log4j.appender.D = org.apache.log4j.DailyRollingFileAppender
log4j.appender.D.File = logs/error.log ## 异常日志文件名
log4j.appender.D.Append = true
log4j.appender.D.Threshold = ERROR ## 只输出ERROR级别以上的日志!!!
log4j.appender.D.layout = org.apache.log4j.PatternLayout
log4j.appender.D.layout.ConversionPattern = %-d{yyyy-MM-dd HH:mm:ss} [ %t:%r ] - [ %p ] %m%n
[代码中使用]
public class TestLog4j {
public static void main(String[] args) {
PropertyConfigurator.configure( " D:/Code/conf/log4j.properties " );
Logger logger = Logger.getLogger(TestLog4j. class );
logger.debug( " debug " );
logger.error( " error " );
}
}