log日志异常堆栈打印的正确姿势

背景:
在业务代码中，发生异常，我们常常习惯把上下文和异常堆栈打印下来，方便排查问题，而 org.slf4j.Logger 接口中常用的方法如下:
以info为例:

  /**
   * Log a message at the INFO level.
   *
   * @param msg the message string to be logged
   */
  public void info(String msg);
/**
   * Log a message at the INFO level according to the specified format
   * and argument.
   * 

   * 
This form avoids superfluous object creation when the logger
   * is disabled for the INFO level. 
   *
   * @param format the format string
   * @param arg    the argument
   */
  public void info(String format, Object arg);
  
  /**
   * Log a message at the INFO level according to the specified format
   * and arguments.
   * 

   * 
This form avoids superfluous object creation when the logger
   * is disabled for the INFO level. 
   *
   * @param format the format string
   * @param arg1   the first argument
   * @param arg2   the second argument
   */
  public void info(String format, Object arg1, Object arg2);
  /**
   * Log a message at the INFO level according to the specified format
   * and arguments.
   * 

   * 
This form avoids superfluous string concatenation when the logger
   * is disabled for the INFO level. However, this variant incurs the hidden
   * (and relatively small) cost of creating an Object[] before invoking the method,
   * even if this logger is disabled for INFO. The variants taking
   * {@link #info(String, Object) one} and {@link #info(String, Object, Object) two}
   * arguments exist solely in order to avoid this hidden cost.
   *
   * @param format    the format string
   * @param arguments a list of 3 or more arguments
   */
  public void info(String format, Object... arguments);
  /**
   * Log an exception (throwable) at the INFO level with an
   * accompanying message.
   *
   * @param msg the message accompanying the exception
   * @param t   the exception (throwable) to log
   */
  public void info(String msg, Throwable t);
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

而针对抛异常的接口似乎只能通过调用,
/**

• Log an exception (throwable) at the INFO level with an
• accompanying message.
• @param msg the message accompanying the exception
• @param t the exception (throwable) to log
  */
  public void info(String msg, Throwable t);
  但是如果这么处理我们就没法打印上下文，如果这么写

log.info("xxx:{},xxxx:{},异常:{}",x1,x2,throwable)
1

能解决打印堆栈的问题吗？
其实不能，那么我们如何处理，难道需要我们先自己把上下文处理好，调用
log.info(msg,throwable) 才能打印吗？
这么做当然能解决，但是 对以前日志的改造工作量大，那么如何处理呢？

正确的姿势:

log.info("xxx:{},xxx:{},异常:",x1,x2,throwable)
1

说明:

1. 异常是最后一个参数
2. 占位符的个数比实际参数要少
   划重点:
   throwable 没有站位符即可，为什么？？？
   我们来分析下源码
   因为我们是使用logback写的日志：

我们以如下代码做例子:

        try {
            int i = 0;
            int j= 5;
            int r = j / i;
        }catch (Exception e){
            log.info("除数:{},被除数:{},异常:",j,i,e);
        }
1
2
3
4
5
6
7

会走到
Logger

ch.qos.logback.classic.Logger下面的
// 此时 argArray 代表的是  【j,i,e】
// format 代表的是 除数:{},被除数:{},异常:
  public void info(String format, Object[] argArray) {
    filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, format, argArray, null);
  }
private void filterAndLog_0_Or3Plus(final String localFQCN,
      final Marker marker, final Level level, final String msg,
      final Object[] params, final Throwable t) {

    final FilterReply decision = loggerContext
        .getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg,
            params, t);

    if (decision == FilterReply.NEUTRAL) {
      if (effectiveLevelInt > level.levelInt) {
        return;
      }
    } else if (decision == FilterReply.DENY) {
      return;
    }
    // 此处替换占位符处理异常
    buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
  }

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

  private void buildLoggingEventAndAppend(final String localFQCN,
      final Marker marker, final Level level, final String msg,
      final Object[] params, final Throwable t) {
      // 此处处理的占位符和异常
    LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
    le.setMarker(marker);
    callAppenders(le);
  }
1
2
3
4
5
6
7
8

LoggingEvent

  public LoggingEvent(String fqcn, Logger logger, Level level, String message,
                      Throwable throwable, Object[] argArray) {
    this.fqnOfLoggerClass = fqcn;
    this.loggerName = logger.getName();
    this.loggerContext = logger.getLoggerContext();
    this.loggerContextVO = loggerContext.getLoggerContextRemoteView();
    this.level = level;

    this.message = message;
    // 此处处理占位符和异常
    FormattingTuple ft = MessageFormatter.arrayFormat(message, argArray);
    // 此处得到的 ft 中，formattedMessage = 除数:5,被除数:0,异常:
    formattedMessage = ft.getMessage();
    // 入参中 throwable 是空，因此会走到此处
    if (throwable == null) {
    // 排除最后一个异常的参数数组 
      argumentArray = ft.getArgArray();
      // 从 FormattingTuple 中得到 异常，也就是 最后一个的异常参数
      throwable = ft.getThrowable();
    } else {
      this.argumentArray = argArray;
    }
    // 真正打印异常日志的在此处
    if (throwable != null) {
    // ThrowableProxy 会提取异常的堆栈日志:
      this.throwableProxy = new ThrowableProxy(throwable);
      LoggerContext lc = logger.getLoggerContext();
      if (lc.isPackagingDataEnabled()) {
        this.throwableProxy.calculatePackagingData();
      }
    }

    timeStamp = System.currentTimeMillis();
  }
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

FormattingTuple

final public static FormattingTuple arrayFormat(final String messagePattern,
      final Object[] argArray) {
      // 提取异常，逻辑：判断参数的最后一个是否是异常
    Throwable throwableCandidate = getThrowableCandidate(argArray);

    if (messagePattern == null) {
      return new FormattingTuple(null, argArray, throwableCandidate);
    }

    if (argArray == null) {
      return new FormattingTuple(messagePattern);
    }

    int i = 0;
    int j;
    StringBuffer sbuf = new StringBuffer(messagePattern.length() + 50);

    int L;
    // 遍历参数
    for (L = 0; L < argArray.length; L++) {
//   static final String DELIM_STR = "{}";
// 查找占位符 DELIM_STR 也就是 {}
      j = messagePattern.indexOf(DELIM_STR, i);
      // 当 参数比占位符 多的时候，会走到此处
      if (j == -1) {
        // no more variables
        if (i == 0) { // this is a simple string
          return new FormattingTuple(messagePattern, argArray,
              throwableCandidate);
        } else { // add the tail string which contains no variables and return
          // the result.
          sbuf.append(messagePattern.substring(i, messagePattern.length()));
          // 再次走到此处，此时，sbuf = 除数:5,被除数:0,异常:，
          // argArray 没变， throwableCandidate 是 我们上面提取出来的异常
          return new FormattingTuple(sbuf.toString(), argArray,
              throwableCandidate);
        }
      } else {
        if (isEscapedDelimeter(messagePattern, j)) {
          if (!isDoubleEscaped(messagePattern, j)) {
            L--; // DELIM_START was escaped, thus should not be incremented
            sbuf.append(messagePattern.substring(i, j - 1));
            sbuf.append(DELIM_START);
            i = j + 1;
          } else {
            // The escape character preceding the delimiter start is
            // itself escaped: "abc x:\\{}"
            // we have to consume one backward slash
            sbuf.append(messagePattern.substring(i, j - 1));
            deeplyAppendParameter(sbuf, argArray[L], new HashMap());
            i = j + 2;
          }
        } else {
          // normal case
          // 找到占位符，并用对应的参数进行替换，并修改 i 为 大于 0的值
          sbuf.append(messagePattern.substring(i, j));
          deeplyAppendParameter(sbuf, argArray[L], new HashMap());
          i = j + 2;
        }
      }
    }
    // append the characters following the last {} pair.
    sbuf.append(messagePattern.substring(i, messagePattern.length()));
    if (L < argArray.length - 1) {
      return new FormattingTuple(sbuf.toString(), argArray, throwableCandidate);
    } else {
      return new FormattingTuple(sbuf.toString(), argArray, null);
    }
  }

  static final Throwable getThrowableCandidate(Object[] argArray) {
    if (argArray == null || argArray.length == 0) {
      return null;
    }

    final Object lastEntry = argArray[argArray.length - 1];
    if (lastEntry instanceof Throwable) {
      return (Throwable) lastEntry;
    }
    return null;
  }
private static void deeplyAppendParameter(StringBuffer sbuf, Object o,
      Map seenMap) {
    if (o == null) {
      sbuf.append("null");
      return;
    }
    // 因为是String类型，此处添加
    if (!o.getClass().isArray()) {
      safeObjectAppend(sbuf, o);
    } else {
      // check for primitive array types because they
      // unfortunately cannot be cast to Object[]
      if (o instanceof boolean[]) {
        booleanArrayAppend(sbuf, (boolean[]) o);
      } else if (o instanceof byte[]) {
        byteArrayAppend(sbuf, (byte[]) o);
      } else if (o instanceof char[]) {
        charArrayAppend(sbuf, (char[]) o);
      } else if (o instanceof short[]) {
        shortArrayAppend(sbuf, (short[]) o);
      } else if (o instanceof int[]) {
        intArrayAppend(sbuf, (int[]) o);
      } else if (o instanceof long[]) {
        longArrayAppend(sbuf, (long[]) o);
      } else if (o instanceof float[]) {
        floatArrayAppend(sbuf, (float[]) o);
      } else if (o instanceof double[]) {
        doubleArrayAppend(sbuf, (double[]) o);
      } else {
        objectArrayAppend(sbuf, (Object[]) o, seenMap);
      }
    }
  }
private static void safeObjectAppend(StringBuffer sbuf, Object o) {
    try {
      String oAsString = o.toString();
      sbuf.append(oAsString);
    } catch (Throwable t) {
      System.err
          .println("SLF4J: Failed toString() invocation on an object of type ["
              + o.getClass().getName() + "]");
      t.printStackTrace();
      sbuf.append("[FAILED toString()]");
    }

  }

走到了

// 再次走到此处，此时，sbuf = 除数:5,被除数:0,异常:，
          // argArray 没变， throwableCandidate 是 我们上面提取出来的异常
  public FormattingTuple(String message, Object[] argArray, Throwable throwable) {
    this.message = message;
    this.throwable = throwable;
    if(throwable == null) {
      this.argArray = argArray;
    } else {
    // 拷贝参数去掉最后一个参数(也就是异常参数)， 此时会回到 LoggingEvent 方法中继续执行
      this.argArray = trimmedCopy(argArray);
    }
  }
static Object[] trimmedCopy(Object[] argArray) {
    if(argArray == null || argArray.length == 0) {
      throw new  IllegalStateException("non-sensical empty or null argument array");
    }
    final int trimemdLen = argArray.length -1;
    Object[] trimmed = new Object[trimemdLen];
    System.arraycopy(argArray, 0, trimmed, 0, trimemdLen);
    return trimmed;
  }
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

ThrowableProxy

public ThrowableProxy(Throwable throwable) {
   
    this.throwable = throwable;
    this.className = throwable.getClass().getName();
    this.message = throwable.getMessage();
    // 此处得到的堆栈的相关信息，因此后续打印中就包含了异常堆栈信息
    this.stackTraceElementProxyArray = 
    ThrowableProxyUtil.steArrayToStepArray(throwable
        .getStackTrace());
    
    Throwable nested = throwable.getCause();
    
    if (nested != null) {
      this.cause = new ThrowableProxy(nested);
      this.cause.commonFrames = ThrowableProxyUtil
          .findNumberOfCommonFrames(nested.getStackTrace(),
              stackTraceElementProxyArray);
    }
    if(GET_SUPPRESSED_METHOD != null) {
      // this will only execute on Java 7
      try {
        Object obj = GET_SUPPRESSED_METHOD.invoke(throwable);
        if(obj instanceof Throwable[]) {
          Throwable[] throwableSuppressed = (Throwable[]) obj;
          if(throwableSuppressed.length > 0) {
            suppressed = new ThrowableProxy[throwableSuppressed.length];
            for(int i=0;i<throwableSuppressed.length;i++) {
              this.suppressed[i] = new ThrowableProxy(throwableSuppressed[i]);
              this.suppressed[i].commonFrames = ThrowableProxyUtil
                  .findNumberOfCommonFrames(throwableSuppressed[i].getStackTrace(),
                      stackTraceElementProxyArray);
            }
          }
        }
      } catch (IllegalAccessException e) {
        // ignore
      } catch (InvocationTargetException e) {
        // ignore
      }
    }

  }
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