Research on the parameter problem of log.warn() of slf4j

1. 背景
今日は @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, "Woooo, something went wrong in some business。", "What should I do if it is swollen？");
}
}
@Test
public void test2() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={},e={}",
500, "Wow, something went wrong in some business。", JSON.toJSONString(e));
}
}
@Test
public void test3() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={},e={}",
500, "Aww, something went wrong in some business。", ExceptionUtils.getStackTrace(e));
}
}
@Test
public void test4() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={}",
500, "Woo, something went wrong in some business。", e);
}
}
private void mockException() {
throw new RuntimeException("A runtime exception");
}
}
考えた後、私の分析と一致するか、それとも違いがあるか確認してください。
三、段階的な分析
まず warn のソースコードを見てみましょう。
/**
* Log a message at the WARN level according to the specified format
* and arguments.
*

*

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 Object[] 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.

*
* @param format the format string
* @param arguments a list of 3 or more arguments
*/
public void warn(String format, Object... arguments);
前半がフォーマット文字列で、後半が対応するパラメーターであることがわかります。フォーマット用のプレースホルダー（「{}」）が後続のパラメーターに一つずつ対応しています。
@Test
public void test0() {
log.warn("code={},msg={}", 200, "Success。");
}
パラメーターは 200（1 番目のパラメーターが 1 番目のプレースホルダーに対応）で、2 番目のパラメーター「Success。」が 2 番目のプレースホルダーに対応します。
ログ出力時の文字列結合結果：code=200, msg=success
出力結果は以下の通りです。
00:05:46.731 [main] WARN com.chujianyun.common.log.WarnLogTest - code=200, msg=success。
期待通りです（前半の部分は自動的に付与され、カスタマイズ可能です）。
プレースホルダーとパラメーターの関係は String.format() 関数とよく似ています。
public static String format(String format, Object... args) {
return new Formatter(). format(format, args). toString();
}
前半がフォーマット文字列で、後半がプレースホルダーに対応するパラメーターです。
以下のコードと同等です（比較しながら学習できます）。
String.format("code=%d,msg=%s", 200, "Success。");
では 1 番目のテストケースを見てください。上記のパラメーターから、プレースホルダー {} は 2 つで後続のパラメーターは 3 つあるため、最後のパラメーターは表示されないと推論できます。
@Test
public void test1() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={}",
500, "Woooo, something went wrong in some business。", "What should I do if it is swollen？");
}
}
実行結果：
23:37:18.525 [main] WARN com.chujianyun.common.log.WarnLogTest - code=500, msg=Woo, something went wrong in a certain business。
やはり予想通りの結果でした。
2 番目のテストケースを見てみましょう。
@Test
public void test2() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={},e={}",
500, "Wow, something went wrong in some business。", JSON.toJSONString(e));
}
}
上記の理論に基づけば、プレースホルダー 3 つとパラメーター 3 つで問題ないはずです。
確かに予想通りでしたが、出力が美しくありません。非常に長く、すべて 1 行で表示されています。
では書き方を変えて、ツールを使って整形してみましょう。
@Test
public void test3() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={},e={}",
500, "Aww, something went wrong in some business。", ExceptionUtils.getStackTrace(e));
}
}
正常に動作します。
もう一つの書き方を見てみましょう。
@Test
public void test4() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={}",
500, "Woo, something went wrong in some business。", e);
}
}
これまでの経験から、e は出力されないはずです。フォーマット用のプレースホルダーが 2 つしかないのに、パラメーターは 3 つあるからです。
しかし結果は予想と違いました。
四、探究
これはインターフェイスです。実装クラスを見てみましょう。
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());
}
}
前半部分は以下を呼び出します。
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);
}
そして以下を呼び出します。
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 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;
}
真相が明らかになりました。
getThrowableCandidate 関数は、配列の最後の要素が Throwable のサブタイプかどうかを判定します。サブタイプであれば Throwable にキャストして前方に返し、そうでなければ null を返します。
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);
}
また、ブレークポイントを設定して確認することもできます（具体的にはステップバイステップで追跡できます）。
また、特別に注意してほしいのは、左下の呼び出しスタックを活用することです。全体の呼び出しチェーンを確認でき、ダブルクリックで上位のソースコードに移動できます。
したがって結論は以下の通りです。
org.slf4j.Logger#warn(java.lang.String, java.lang.Object...) を使用する際、最後のパラメーターが例外の場合、ログに自動的に追記されます。
アダプターパターンのおかげで、基盤となる実装がこの互換性を提供しています。
なお、ここでアダプターと呼ばれる理由については、記事末尾のもう一つの記事「SLF4J の利点と原理」を参照してください。
五、まとめ
1. 予想と異なるコードに遭遇したら、必ずこの機会に調査し、より深く学んでください。これまで気に留めなかったことや、十分理解できていなかった点が発見できるかもしれません。また、潜在的なリスクやバグを発見する可能性もあります。
2. 問題に遭遇した際はソースコードを追跡し、ソースコードの観点から原因を分析してみてください。これは急速に成長する方法の一つです。
3. コードの実行状況を検証するには、ブレークポイントを活用してください。これは実践的な経験です。