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

1. Background
Today we discuss the parameters of @Slf4j's log.warn().
Second, upload the source code
Let me give the following test cases first. Think about what will be output respectively?
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");
}
}
After thinking about it, see if it is the same as my analysis or there is a discrepancy.
Three, step by step analysis
Let's first look at the source code of 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);
It is found that the front is the format format string, followed by the corresponding parameters. The formatted placeholders (that is, "{}") correspond to the following parameters one by one.
@Test
public void test0() {
log.warn("code={},msg={}", 200, "Success!");
}
The parameter refers to 200 (the first parameter corresponds to the first placeholder), and the second parameter "Success!" corresponds to the second placeholder.
Stitching together when outputting logs: code=200, msg=success
The output is:
00:05:46.731 [main] WARN com.chujianyun.common.log.WarnLogTest - code=200, msg=success!
As expected (the front is automatically appended and can be customized).
The placeholders and parameters are very similar to the String.format() function
public static String format(String format, Object... args) {
return new Formatter(). format(format, args). toString();
}
The front is the format string, followed by the parameters corresponding to the placeholders.
Equivalent to the following code (we can compare and learn):
String.format("code=%d,msg=%s", 200, "Success!");
So look at the first one. According to the above parameters, we can infer that the previous {} is a placeholder, there are two, and there are three subsequent parameters. The last one should not be displayed.
@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?");
}
}
operation result:
23:37:18.525 [main] WARN com.chujianyun.common.log.WarnLogTest - code=500, msg=Woo, something went wrong in a certain business!
Sure enough, it is the same as we thought! !
Let's look at the second one:
@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));
}
}
According to the above theory, three placeholders and three parameters should be fine.
Although it is the same as we thought, but the printing is too inelegant, it is very long and all in one line! ! !
Then let's change the way of writing and use tools to beautify it:
@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));
}
}
It works fine:
Let's look at another way of writing:
@Test
public void test4() {
try {
mockException();
} catch (Exception e) {
log.warn("code={},msg={}",
500, "Woo, something went wrong in some business!", e);
}
}
According to the previous experience, we think that this should not print e, because there are only two formatting placeholders, and this is three parameters.
We found out that the results were not what we thought! ! !
4. Explore
It is an interface, let's look at its implementation class
Let's take Log4JLoggerAdapter as an example. You can see the adapter mode by looking at the name.
The purpose of the adapter pattern: to convert the interface of a class into another interface that the client wants.
The Adapter pattern enables classes that would otherwise not work together due to incompatible interfaces to work together.
If you want to study in detail, you can see the references at the end of the article.
We continue and find that the implemented code is here (here is the adapted function):
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());
}
}
The first half calls here:
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);
}
and call here
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;
}
and here
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;
}
The truth emerges!
The getThrowableCandidate function will judge whether the last one of the array is a subtype of Throwable, if it is converted into Throwable and return to the front, otherwise it will return null.
The trimmedCopy(Object[] argArray) function only copies the parameter length -1 length, ignoring the last element.
Finally call org.slf4j.helpers.MessageFormatter#arrayFormat(java.lang.String, java.lang.Object[], java.lang.Throwable) to construct the printing object FormattingTuple.
Then call log4j's
org.apache.log4j.Category#log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable) to achieve printing.
public void log(String FQCN, Priority p, Object msg, Throwable t) {
int levelInt = this. priorityToLevelInt(p);
this.differentiatedLog((Marker)null, FQCN, levelInt, msg, t);
}
In addition, we can also break the point to verify (specifically, we can follow it step by step).
In addition, a special reminder, make good use of the call stack in the lower left corner, you can see the entire call link, double-click to switch to the upper source code.
So the conclusion is:
When using org.slf4j.Logger#warn(java.lang.String, java.lang.Object...), if the last parameter is an exception, it can be automatically appended to the log.
Thanks to the Adapter pattern, the underlying implementation provides this compatibility.
In addition, why the adapter is called here, you can read my other article "Advantages and Principles of Slf4j" at the end of the article.
V. Summary
1. If you encounter a code that does not match your expectations, you must take the opportunity to study it and learn more. You may find something you didn't pay attention to, a point you didn't grasp well, or you may find a hidden danger or BUG.
2. Try to follow the source code when encountering problems, and analyze why from the source code perspective, which is a way to grow rapidly.
3. Verify whether the code is running, you can break the point, this is an experience.