Java Logging Part 5: Best Practices

By Shangzuo

1. Always Use the Interface Layer

When writing code or implementing a third-party tool, always log at the interface layer.

If you need to provide a third-party tool externally, remember to mark the logging implementation and adaptation layers as optional in the dependencies, for example:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-core</artifactId>
  <version>${logback.version}</version>
  <scope>runtime</scope>
  <optional>true</optional>
</dependency>

A simple explanation:

• <scope>runtime</scope>: The package of the runtime will be ignored during compilation (it is considered that the runtime environment already has the corresponding package);
• <optional>true</optional>: Dependencies will not be passed, and Maven will not automatically install this package;

2. Do Not Print the Separator Line

Don't print content like this that only contains a separator line: log.info("========== start =========="), because the next line of this log is likely to come from other asynchronous tasks. If SLS is used to collect or even come from another machine, this separator line will not work at all.

The correct way is to mark by keywords, such as log.info("FooBarProcessor start, request={}", request), and then quickly filter by keyword FooBarProcessor, which is applicable to both grep and SLS.

In addition, Marker can be used to make log semantics clearer (please refer to section 4. Marker in part 3, but it is a little troublesome and depends on personal preferences.

3. Avoid Throwing Errors Due to Writing Logs

For example, it calls its method directly without an empty sentence:

Object result = rpcResource.call();

// If the result is null, the NPE is thrown.
log.info("result.userId={}", result.getUserId());

This is an old topic, so we won't elaborate on it here.

4. Two Fastjson Parameters

4.1 IgnoreErrorGetter

Fastjson serialization actually depends on each getter in the class. If a getter throws an exception, the entire serialization will be blocked. However, some getter exceptions are not serious problems. In this case, you can use the SerializerFeature.IgnoreErrorGetter parameter to ignore the exception thrown in the getter:

public class Foo {
    private Long userId;
    @Deprecated
    private Long accountId;

// The getter is thrown with an exception.
    public Long getAccountId() {
        throw new RuntimeException("Please use userId");
}
}

// In this way, the log will not be blocked by the exception thrown by getter.
log.info("foo={}", JSON.toJSONString(foo, SerializerFeature.IgnoreErrorGetter));

4.2 IgnoreNonFieldGetter

For example, there is a Result wrapper class as follows (note the isError method), which will output "error":false when serialized by Fastjson. If you want to ignore getter methods like this that do not correspond to entity fields, you can append the SerializerFeature.IgnoreNonFieldGetter parameters:

@Data
public class Result<T> {
    private boolean success;
    private T data;

    public boolean isError() {
        return !success;
    }
}

// If the log is printed in this way, there will be no "error": false
log.info("result={}", JSON.toJSONString(result, SerializerFeature.IgnoreNonFieldGetter));

This parameter is very helpful for printing the Result wrapper class. If the "error": false is printed out, then when you want to use the error keyword query error, it will match a lot of containing errors, but not the error of the invalid data.

5. Don't Miss the Exception Stack

As we mentioned in the section 3.1. info method of the part 3, exception parameters do not occupy character templates. If your number of parameters does not match, it is likely that the printed results do not match expectations.

For example:

Exception e = new RuntimeException("blahblahblah");
log.error("exception={}", e); // In this case, IDEA will give a warning: there are fewer parameters than placeholders.

At this time, since the e matches the corresponding {} position, Slf4j will try to convert the exception into a string and put it into the log template. The final sentence is equivalent to:

log.error("exception={}", e.toString());

In the end, you only get the exception=blahblahblah and the stack is lost.

The correct approach is to ensure that the exception parameter does not occupy the character template:

// After using e.getMessage() to spell the log, there is a separate e for printing the stack at the same time.
log.error("exception={}", e.getMessage(), e);

The final output will be:

exception=blahblahblah
There will be stack information after line break

6. Limit Log Output Length

6.1 Limit Maximum Log Text Length

Sometimes, when we pass a very large POJO,

log.info("result={}", JSON.toJSONString(result))

When you print a log, the entire log becomes very long. Not only does it affect performance, but such a large result is not necessarily helpful for actual problem troubleshooting.

You can refer to the section 3.2 Format modifiers of the part 4 to limit the maximum length of the message and discard the excess part:

%.-2000message

6.2 Limit the Level of the Stack

In fact, Logback has native support, such as %exception{50}, which can limit the printout to 50 levels. Additionally, Logback provides more control over the exception stack. For more details, please refer to Evaluators [1].

7. Merge Stacks into One Row

Some students want to stack the output on one line to ensure that the expected records are retained when performing multi-layer grep through the pipeline |.

In fact, this capability can be supported through Logback configuration. We can use the %replace:

%replace(%exception){'[\r\n\t]+', '    '}%nopex

Briefly explain:

• %replace(p){r, t}: Match the given p with regular r, and replace the hit with t, so the above is to replace the [\r\n\t] (i.e. line feed, carriage return, Tab) in the %exception with (four spaces);
• %nopex: If not, Logback will automatically append the %exception to the end of the log, causing the exception stack to be typed twice (one with our own conversion to one line and one with the original line feed);

If you have requirements on the length of the exception stack, you can refer to section 3.2. Format modifiers and section 6. limiting the length of log output of the part 4, we can also do this:

%.-10000replace(%exception{50}){'[\r\n\t]+', '    '}%nopex

as shown in the following code:

• Print only the first 50 layers of the stack;

• After converting to a line, the maximum length is limited to 10000, and the part exceeding the length is discarded.

8. %method and %line Are Not Recommended

In the configuration of Logback, you can output the method name and line number by %method and %line. However, these two items depend on the current stack trace, and the cost of obtaining the stack trace is relatively high. The log will occupy a large number of CPUs, so in general, we recommend that you do not output these fields in the log.

If the other legal name has output requirements, you can directly hard-code it into the output string, for example:

log.info("queryUserInfo, request={}, result={}", request, result);

9. Do Not Output Logs to the Console

When we call the System.out.println, the default output location is the console. Logback also provides a ch.qos.logback.core.ConsoleAppender to output logs to the console.

However,

• Once the machine is online, no one will be watching the console, so logging to the console is pointless and a waste of machine resources.

• When debugging locally, it's better to add breakpoints or search log files, and there's generally no need to check the console output.

• When the main function is used to run the test code, it's better to use System.out.println and not involve the logging system.

10. Useless LogUtil

Recently, I took over some projects and found that an additional custom utility class LogUtil was used for logging. However, if you take a closer look at the code, you will find that it just implements the existing capabilities of Slf4j or Logback again, including but not limited to:

To realize the splicing of log content, please refer to the section o3.1 info method in the third article.
Implement log parameters to JSON by default;
Log truncation exceeds the maximum length. For more information, please refer to section 6.1 Limit the Maximum Length of Log Text of this article.
Merge the exception stacks on the same line for output. For more information, please refer to section 7. Merge Stacks into One Row of this article.
Control whether to print certain logs through dynamic switches;
Append traceId to the log. For more information, please refer to Section 5 in the third article and Section 5. traceId in MDC in the fourth article.

11. A Small Detail

Please look at the following code first:

@Data
public class Foo {
    private String bar;
}

Foo foo = new Foo();
foo.setBar("baz");

// Scenario 1 (note the colon in the first parameter)
log.info("foo:{}", foo);
// Output foo:Foo{bar=baz}

// Scenario 2 (note the equal sign in the first parameter)
log.info("foo={}", JSON.toJSONString(foo));
// Output foo={"bar":"baz"}

Have you noticed the difference between the two scenarios?

In Scenario 1, we use Lombok's @ToString to convert strings, where key-value pairs are separated by an equal sign =. Therefore, we suggest using a colon to quickly distinguish recorded information when viewing logs.

In contrast, in Scenario 2, we recommend using an equal sign because key-value pairs are separated by colons : in the JSON format.

References:

[1] https://logback.qos.ch/manual/layouts.html#Evaluators
[2] https://github.com/alibaba/p3c
[3] https://github.com/alibaba/p3c/blob/master/p3c-gitbook/异常日志/日志规约.md

Disclaimer: The views expressed herein are for reference only and don't necessarily represent the official views of Alibaba Cloud.

Community

Java Logging Part 5: Best Practices

1. Always Use the Interface Layer

2. Do Not Print the Separator Line

3. Avoid Throwing Errors Due to Writing Logs

4. Two Fastjson Parameters

4.1 IgnoreErrorGetter

4.2 IgnoreNonFieldGetter

5. Don't Miss the Exception Stack

6. Limit Log Output Length

6.1 Limit Maximum Log Text Length

6.2 Limit the Level of the Stack

7. Merge Stacks into One Row

8. %method and %line Are Not Recommended

9. Do Not Output Logs to the Console

10. Useless LogUtil

11. A Small Detail

References:

Read previous post:

Read next post:

Alibaba Cloud Community

You may also like

Comments

Alibaba Cloud Community

Related Products

Best Practices

Web Hosting Solution

YiDA Low-code Development Platform

Web Hosting