自定义Logback输出格式：掌握JSON日志的奥秘

说到 log4j, 基本人人都知道, 但是 logback, 估计用的人不多, 其实这两个都是 sl4j 的实现, 而且是一个作者写的.

logback 比 log4j 更加好用, 而且效率更高.

如何配置 logback.

1
2
3
4
5
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.1.3</version>
</dependency>

配置文件: logback.xml

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
<?xml version="1.0" encoding="UTF-8" ?>
<configuration scan="true" scanPeriod="10 minutes">
 <property name="LOG_HOME" value="d:/logs"/>

 <appender name="stdot" class="ch.qos.logback.core.ConsoleAppender">
  <layout class="ch.qos.logback.classic.PatternLayout">
   <pattern>%d{yyyy-MM-dd HH:mm:ss} [%p][%c][%M][%L]-> %m%n</pattern>
  </layout>
 </appender>
 <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
   <FileNamePattern>${LOG_HOME}/log.%d{yyyy-MM-dd}(%i).log</FileNamePattern>
   <cleanHistoryOnStart>true</cleanHistoryOnStart>
   <TimeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
    <MaxFileSize>10MB</MaxFileSize>
   </TimeBasedFileNamingAndTriggeringPolicy>
  </rollingPolicy>
  <encoder>
    <charset>utf-8</charset>
    <pattern>%d{yyyy-MM-dd HH:mm:ss} [%p][%c][%M][%L]-> %m%n</pattern>
  </encoder>
  <append>false</append>
  <prudent>false</prudent>
 </appender>

 <logger name="org.mortbay.log" additivity="false"  level="ERROR">
       <appender-ref ref="stdot" />
 </logger>

 <logger name="org.mybatis.spring" additivity="false"  level="ERROR">
       <appender-ref ref="stdot" />
 </logger>

 <root level="debug">
  <appender-ref ref="stdot" />
  <appender-ref ref="file" />
 </root>

</configuration>

将这个文件放到资源目录根目录下, 服务器启动时, logback 会根据 logback 这个名称自己去匹配加载

这里如果要输出项目中的 SQL 很简单, 只需要将日志级别改成 debug 就可以了（mybatis 是这样的, 其他的没试过）

今天主要说的是日志格式

%d{yyyy-MM-dd HH:mm:ss} [%p][%c][%M][%L]-> %m%n

这里就是配置格式的, 以下是各个参数的说明

参数 说明
%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)

这个时候, 日志就会输出 时间, 日志优先级, 类名, 方法名, 行数, 日志内容

基本就是这样的了

1
2
3
2016-09-02 14:45:53 [DEBUG][com.ulewo.mapper.SignInMapper.selectCount][debug][132]-> ==>  Preparing: select count(1) from ulewo_sign_in WHERE sign_date = DATE_FORMAT(?,'%Y-%m-%d')
2016-09-02 14:45:53 [DEBUG][com.ulewo.mapper.SignInMapper.selectCount][debug][132]-> ==> Parameters: 2016-09-02 14:45:53.098(Timestamp)
2016-09-02 14:45:53 [DEBUG][com.ulewo.mapper.SignInMapper.selectCount][debug][132]-> <==      Total: 1

这里输出了 SQL.

为什么要讲输出格式, 本来这样输出挺好的呀, 是的, 现在在我们的生产环境中, 总共有 16 台服务器, 有时候查问题, 要一台台的查, 因为不知道请求到底是大到那个服务器上,
这样查问题非常的痛苦, 于是项目引入了 graylog 一个日志收集工具, 可以将各个服务器的日志收集到一起, 这样查问题就方便多了. 但是 graylog 要求日志必须是
json 格式的, 那么按照我上面格式就无法使用了, 所以要修改日志输出格式.

查了一番资料发现, 只要重写 ClassicConverter 和 PatternLayout 这两个类就可以了

重新 Converter 类

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
public class NetbarLogerConvert extends ClassicConverter {

 long lastTimestamp = -1;
 String timestampStrCache = null;
 SimpleDateFormat simpleFormat = null;

 String businessName = null;

 static String hostName;
 static String localIp;

 static {
  InetAddress ia = null;
  try {
   ia = ia.getLocalHost();
   hostName = ia.getHostName();
   localIp = ia.getHostAddress();
  } catch (Exception e) {
   // TODO Auto-generated catch block
   e.printStackTrace();
  }
 }

 @Override
 public String convert(ILoggingEvent le) {
  LogObject log = new LogObject();
  log.setBusiness(businessName);
  log.setIp(localIp);
  log.setHostName(hostName);
  log.setTime(getTime(le));
  log.setLeave(le.getLevel().toString());
  log.setClassName(getFullyQualifiedName(le));
  log.setMethodName(getMethodName(le));
  log.setLine(getLineNumber(le));
  log.setMessage(le.getFormattedMessage());
  return JacksonUtil.writJson(log);
 }

 public void start() {
  businessName = getFirstOption();
  businessName = businessName == null ? "未设置产品线" : businessName;
  String datePattern = DateStyle.YYYY_MM_DD_HH_MM_SS.getValue();
  try {
   simpleFormat = new SimpleDateFormat(datePattern);
   // maximumCacheValidity =
   // CachedDateFormat.getMaximumCacheValidity(pattern);
  } catch (IllegalArgumentException e) {
   addWarn("Could not instantiate SimpleDateFormat with pattern " + datePattern, e);
   // default to the ISO8601 format
   simpleFormat = new SimpleDateFormat(CoreConstants.ISO8601_PATTERN);
  }
  List optionList = getOptionList();
  // if the option list contains a TZ option, then set it.
  if (optionList != null && optionList.size() > 1) {
   TimeZone tz = TimeZone.getTimeZone((String) optionList.get(1));
   simpleFormat.setTimeZone(tz);
  }
 }

 private String getTime(ILoggingEvent le) {
  long timestamp = le.getTimeStamp();
  synchronized (this) {
   // if called multiple times within the same millisecond
   // return cache value
   if (timestamp == lastTimestamp) {
    return timestampStrCache;
   } else {
    lastTimestamp = timestamp;
    // SimpleDateFormat is not thread safe.
    // See also http://jira.qos.ch/browse/LBCLASSIC-36
    timestampStrCache = simpleFormat.format(new Date(timestamp));
    return timestampStrCache;
   }
  }
 }

 private String getFullyQualifiedName(ILoggingEvent le) {

  StackTraceElement[] cda = le.getCallerData();
  if (cda != null && cda.length > 0) {
   return cda[0].getClassName();
  } else {
   return CallerData.NA;
  }
 }

 private String getLineNumber(ILoggingEvent le) {
  StackTraceElement[] cda = le.getCallerData();
  if (cda != null && cda.length > 0) {
   return Integer.toString(cda[0].getLineNumber());
  } else {
   return CallerData.NA;
  }
 }

 private String getMethodName(ILoggingEvent le) {
  StackTraceElement[] cda = le.getCallerData();
  if (cda != null && cda.length > 0) {
   return cda[0].getMethodName();
  } else {
   return CallerData.NA;
  }
 }

 public class LogObject {
  /**
   * 产品线
   */
  private String business;
  /**
   * 主机名
   */
  private String hostName;
  /**
   * IP
   */
  private String ip;
  /**
   * 时间
   */
  private String time;
  /**
   * 日志级别
   */
  private String leave;
  /**
   * 类名
   */
  private String className;
  /**
   * 方法名
   */
  private String methodName;
  /**
   * 行数
   */
  private String line;
  /**
   * 日志内容
   */
  private String message;

  public String getTime() {
   return time;
  }

  public void setTime(String time) {
   this.time = time;
  }

  public String getLeave() {
   return leave;
  }

  public void setLeave(String leave) {
   this.leave = leave;
  }

  public String getClassName() {
   return className;
  }

  public void setClassName(String className) {
   this.className = className;
  }

  public String getMethodName() {
   return methodName;
  }

  public void setMethodName(String methodName) {
   this.methodName = methodName;
  }

  public String getLine() {
   return line;
  }

  public void setLine(String line) {
   this.line = line;
  }

  public String getMessage() {
   return message;
  }

  public void setMessage(String message) {
   this.message = message;
  }

  public String getBusiness() {
   return business;
  }

  public void setBusiness(String business) {
   this.business = business;
  }

  public String getIp() {
   return ip;
  }

  public void setIp(String ip) {
   this.ip = ip;
  }

  public String getHostName() {
   return hostName;
  }

  public void setHostName(String hostName) {
   this.hostName = hostName;
  }

 }
}

重写 layout 类

1
2
3
4
5
public class NetbarLoggerPatternLayout extends PatternLayout {
 static {
  defaultConverterMap.put("netbarLoggerPattern", NetbarLogerConvert.class.getName());
 }
}

这里如何获取 方法名, 行数, 甚至还有其他的一些信息可以参考 logback

这个类:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
public class PatternLayout extends PatternLayoutBase<ILoggingEvent> {

  public static final Map<String, String> defaultConverterMap = new HashMap<String, String>();

  static {

    defaultConverterMap.put("d", DateConverter.class.getName());
    defaultConverterMap.put("date", DateConverter.class.getName());

    defaultConverterMap.put("r", RelativeTimeConverter.class.getName());
    defaultConverterMap.put("relative", RelativeTimeConverter.class.getName());

    defaultConverterMap.put("level", LevelConverter.class.getName());
    defaultConverterMap.put("le", LevelConverter.class.getName());
    defaultConverterMap.put("p", LevelConverter.class.getName());

    defaultConverterMap.put("t", ThreadConverter.class.getName());
    defaultConverterMap.put("thread", ThreadConverter.class.getName());

    defaultConverterMap.put("lo", LoggerConverter.class.getName());
    defaultConverterMap.put("logger", LoggerConverter.class.getName());
    defaultConverterMap.put("c", LoggerConverter.class.getName());

    defaultConverterMap.put("m", MessageConverter.class.getName());
    defaultConverterMap.put("msg", MessageConverter.class.getName());
    defaultConverterMap.put("message", MessageConverter.class.getName());

    defaultConverterMap.put("C", ClassOfCallerConverter.class.getName());
    defaultConverterMap.put("class", ClassOfCallerConverter.class.getName());

    defaultConverterMap.put("M", MethodOfCallerConverter.class.getName());
    defaultConverterMap.put("method", MethodOfCallerConverter.class.getName());

    defaultConverterMap.put("L", LineOfCallerConverter.class.getName());
    defaultConverterMap.put("line", LineOfCallerConverter.class.getName());

    defaultConverterMap.put("F", FileOfCallerConverter.class.getName());
    defaultConverterMap.put("file", FileOfCallerConverter.class.getName());

    defaultConverterMap.put("X", MDCConverter.class.getName());
    defaultConverterMap.put("mdc", MDCConverter.class.getName());

    defaultConverterMap.put("ex", ThrowableProxyConverter.class.getName());
    defaultConverterMap.put("exception", ThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("throwable", ThrowableProxyConverter.class
        .getName());

    defaultConverterMap.put("xEx", ExtendedThrowableProxyConverter.class.getName());
    defaultConverterMap.put("xException", ExtendedThrowableProxyConverter.class
        .getName());
    defaultConverterMap.put("xThrowable", ExtendedThrowableProxyConverter.class
        .getName());

    defaultConverterMap.put("nopex", NopThrowableInformationConverter.class
        .getName());
    defaultConverterMap.put("nopexception",
        NopThrowableInformationConverter.class.getName());

    defaultConverterMap.put("cn", ContextNameAction.class.getName());
    defaultConverterMap.put("contextName", ContextNameConverter.class.getName());

    defaultConverterMap.put("caller", CallerDataConverter.class.getName());

    defaultConverterMap.put("marker", MarkerConverter.class.getName());

    defaultConverterMap.put("property", PropertyConverter.class.getName());


    defaultConverterMap.put("n", LineSeparatorConverter.class.getName());
  }

  public PatternLayout() {
    this.postCompileProcessor = new EnsureExceptionHandling();
  }

  public Map<String, String> getDefaultConverterMap() {
    return defaultConverterMap;
  }

  public String doLayout(ILoggingEvent event) {
    if (!isStarted()) {
      return CoreConstants.EMPTY_STRING;
    }
    return writeLoopOnConverters(event);
  }

}

这里有各个参数 convert 的实现, 直接拷贝过来就可以了.

然后 logback 这里的配置修改下

1
2
3
4
5
<appender name="stdot" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="com.stnts.netbar.logger.NetbarLoggerPatternLayout">
    <pattern>%netbarLoggerPattern{XXX 系统}</pattern>
    </layout>
</appender>

上面 layout 的 class 指定为你重写的 class,pattern 中用你自己定义的 pattern 名后面大括号是定义产品线的

这个时候日志就是这样输出的:

1
{"message":"[微信公众帐号][定时刷新 AccessToken 的定时器] redis 中获取的 accessToken 的过期时间: 7200 秒","methodName":"refresh","className":"xxx.xxx.xxx.class","hostName":"pcname","time":"2016-09-02 14:40:00","leave":"INFO","line":"50","business":"xxxx 系统","ip":"192.168.32.115"}

就是一个完整的 json 了.

当然你觉得这样的日志格式, 你看起来还不舒服, 可以自己去定义了.