天天看點

slf4j的log.warn()的參數問題研究

一、背景

今天我們探讨一下@Slf4j的log.warn()的參數問題。

二、上源碼

我先給出下面的幾個測試用例,大家想想分别會輸出什麼?

import com.alibaba.fastjson.JSON;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.exception.ExceptionUtils;
import org.junit.Test;
@Slf4j
public class WarnLogTest {
    @Test
    public void test1() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "嗚嗚,某某業務出錯了!", "腫麼辦?");
        }
    }
    @Test
    public void test2() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "嗚嗚,某某業務出錯了!", JSON.toJSONString(e));
        }
    }
    @Test
    public void test3() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "嗚嗚,某某業務出錯了!", ExceptionUtils.getStackTrace(e));
        }
    }
    @Test
    public void test4() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "嗚嗚,某某業務出錯了!", e);
        }
    }
    private void mockException() {
        throw new RuntimeException("某個運作時異常");
    }
}      
slf4j的log.warn()的參數問題研究

想好之後看看和我的分析是一樣還是有出入。

三、分步解析

我們先看下warn的源碼

/**
     * Log a message at the WARN level according to the specified format
     * and arguments.
     * <p/>
     * <p>This form avoids superfluous string concatenation when the logger
     * is disabled for the WARN level. However, this variant incurs the hidden
     * (and relatively small) cost of creating an <code>Object[]</code> before invoking the method,
     * even if this logger is disabled for WARN. The variants taking
     * {@link #warn(String, Object) one} and {@link #warn(String, Object, Object) two}
     * arguments exist solely in order to avoid this hidden cost.</p>
     *
     * @param format    the format string
     * @param arguments a list of 3 or more arguments
     */
    public void warn(String format, Object... arguments);      
slf4j的log.warn()的參數問題研究

發現前面是format格式化字元串,後面是對應的參數。格式化的占位符(即“{}”)和後面的參數一一對應。

@Test
    public void test0() {
        log.warn("code={},msg={}", 200, "成功!");
    }      
slf4j的log.warn()的參數問題研究

參數指  200(第一個參數,對應第一個占位符),第二個參數“成功!”對應第二個占位符。

輸出日志時拼接在一起:code=200,msg=成功

輸出結果為:

00:05:46.731 [main] WARN com.chujianyun.common.log.WarnLogTest - code=200,msg=成功!

和設想的一樣(前面是自動追加的可以定制)。

這個占位符和參數和String.format()函數非常相似

public static String format(String format, Object... args) {
        return new Formatter().format(format, args).toString();
    }      
slf4j的log.warn()的參數問題研究

前面是格式化字元串,後面是對應占位符的參數。

等價于以下代碼(我們可以對比學習):

String.format("code=%d,msg=%s", 200, "成功!");      
slf4j的log.warn()的參數問題研究

是以看第一個,根據上面的參數我們可以推測到,前面的{}是占位符,有兩個,後面參數有三個,應該最後一個不顯示

@Test
    public void test1() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "嗚嗚,某某業務出錯了!", "腫麼辦?");
        }
    }      
slf4j的log.warn()的參數問題研究

運作結果:

23:37:18.525 [main] WARN com.chujianyun.common.log.WarnLogTest - code=500,msg=嗚嗚,某某業務出錯了!

果然和我們想的一樣!!

我們看第二個:

@Test
    public void test2() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "嗚嗚,某某業務出錯了!", JSON.toJSONString(e));
        }
    }      
slf4j的log.warn()的參數問題研究

根據上面的理論,三個占位符,三個參數應該沒問題。

slf4j的log.warn()的參數問題研究

雖然和我們想的一樣,但是列印的太不優雅了,好長而且都在一行裡!!!

那我們換一個寫法,采用工具類美化一下:

@Test
    public void test3() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "嗚嗚,某某業務出錯了!", ExceptionUtils.getStackTrace(e));
        }
    }      
slf4j的log.warn()的參數問題研究

效果還不錯:

slf4j的log.warn()的參數問題研究

我們再看另外一個寫法:

@Test
    public void test4() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "嗚嗚,某某業務出錯了!", e);
        }
    }      
slf4j的log.warn()的參數問題研究

根據前面的經驗,我們認為這個應該不會列印e,因為格式化占位符隻有兩個,這個是三個參數。

slf4j的log.warn()的參數問題研究

我們發現結果和我們想的不一樣!!!

四、探究

它是一個接口,我們看看他的實作類

slf4j的log.warn()的參數問題研究

我們以Log4JLoggerAdapter為例吧,看名字就知道是擴充卡模式。

擴充卡模式的目的:将一個類的接口轉換成客戶希望的另外一個接口。

擴充卡模式使得原本由于接口不相容而不能一起工作的那些類可以一起工作。

如果想仔細研究可以看文末的參考資料。

我們繼續,發現實作的代碼在這裡(這裡是适配的函數):

org.slf4j.impl.Log4jLoggerAdapter#warn(java.lang.String, java.lang.Object...)

public void warn(String format, Object... argArray) {
        if (this.logger.isEnabledFor(Level.WARN)) {
            FormattingTuple ft = MessageFormatter.arrayFormat(format, argArray);
            this.logger.log(FQCN, Level.WARN, ft.getMessage(), ft.getThrowable());
        }
    }      
slf4j的log.warn()的參數問題研究

上半部分調用了這裡:

final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray) {
        Throwable throwableCandidate = getThrowableCandidate(argArray);
        Object[] args = argArray;
        if (throwableCandidate != null) {
            args = trimmedCopy(argArray);
        }
        return arrayFormat(messagePattern, args, throwableCandidate);
    }      
slf4j的log.warn()的參數問題研究

然後調用到了這裡

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;
    }      
slf4j的log.warn()的參數問題研究

和這裡

private 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;
    }      
slf4j的log.warn()的參數問題研究

真相就浮現了!

getThrowableCandidate函數會判斷數組最後一個是不是Throwable的子類型,如果是轉成Throwable傳回給前面,否則傳回null.      
slf4j的log.warn()的參數問題研究

而trimmedCopy(Object[] argArray)函數隻複制了參數長度-1個長度,忽略最後一個元素。

最終調用org.slf4j.helpers.MessageFormatter#arrayFormat(java.lang.String, java.lang.Object[], java.lang.Throwable)去構造列印對象FormattingTuple。

然後調用log4j的

org.apache.log4j.Category#log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable)來實作列印。

public void log(String FQCN, Priority p, Object msg, Throwable t) {
        int levelInt = this.priorityToLevelInt(p);
        this.differentiatedLog((Marker)null, FQCN, levelInt, msg, t);
    }      
slf4j的log.warn()的參數問題研究

另外我們還可以打斷點驗證一下(具體自己可單步跟下去)。

slf4j的log.warn()的參數問題研究

另外特别提示,善用左下角的調用棧,可以看到整個調用鍊路,輕按兩下可以切到上層源碼。

是以結論是:

使用org.slf4j.Logger#warn(java.lang.String, java.lang.Object...)時,最後一個參數如果是異常可自動追加到日志中。

這得益于擴充卡模式,底層實作提供了這種相容。

另外為什麼會調用到擴充卡這裡,可以看文末的我的另外一篇文章《Slf4j的優勢與原理》。

五、總結

一、遇到和自己預期不符的代碼,一定要借機研究一下,能夠學到更多。可能發現自己沒注意的點,沒掌握好的點,也可能會發現一個隐患或者BUG。

二、遇到問題盡量跟到源碼裡,從源碼角度去分析為什麼,是快速成長的一個途徑。

三、驗證代碼是否運作,可以斷點,這是一個經驗。

附錄:

擴充卡模式 

https://www.runoob.com/design-pattern/adapter-pattern.html

Slf4j的優勢與原理:

https://blog.csdn.net/w605283073/article/details/89683847