13 Logging Logging Is Not as Simple as You Think #
Today, I want to share with you some pitfalls that you may encounter when logging.
Some of you may say that logging is simple, it’s just a matter of using a few commonly used API methods like debug, info, warn, error. But I have seen many pitfalls caused by logging, and the main reasons for mistakes are:
There are many logging frameworks, and different libraries may use different logging frameworks, which creates compatibility issues.
The configuration is complex and prone to errors. Log configuration files are usually complicated, so some developers may just copy a configuration file from another project or the internet without knowing how to modify it or even modify it randomly, which leads to many problems such as duplicate logging, performance issues with synchronous logging, and incorrect configuration for asynchronous logging.
There are some misconceptions about logging itself, such as not considering the cost of retrieving log content and using log levels randomly.
Logback, Log4j, Log4j2, commons-logging, and JDK’s java.util.logging are all logging frameworks in the Java ecosystem and there are indeed many of them. Furthermore, different libraries may choose to use different logging frameworks. As a result, it becomes very challenging to manage logs uniformly. To solve this problem, we have SLF4J (Simple Logging Facade For Java), as shown in the following diagram:
SLF4J provides three main functionalities:
First, it provides a unified logging facade API, represented by the purple section in the diagram, which implements a neutral logging API.
Second, it provides bridging functionality, represented by the blue section in the diagram, which bridges various logging framework APIs (represented by the green section) to the SLF4J API. This means that even if your program uses various logging APIs to log, they can all be bridged to the SLF4J facade API.
Third, it provides adaptation functionality, represented by the red section in the diagram, which binds the SLF4J API to actual logging frameworks (represented by the gray section). SLF4J is just a logging standard, and we still need an actual logging framework. Since logging frameworks do not implement the SLF4J API themselves, a prior conversion is needed. Logback is an implementation of the SLF4J API standard, so no binding module is required for conversion.
It is important to note that although we can use log4j-over-slf4j to bridge Log4j to SLF4J, and we can use slf4j-log4j12 to adapt SLF4J to Log4j, and I’ve put them in the same column in the diagram, we cannot use them together, otherwise a recursive loop will occur. The same applies to jcl and jul.
Although there are four gray-colored logging implementation frameworks in the diagram, the most widely used ones that I have seen in business systems are Logback and Log4j. They were developed by the same person. Logback can be considered as an improved version of Log4j, and I highly recommend using it. Therefore, when it comes to log framework configuration examples, I will focus on Logback.
Spring Boot is currently the most popular Java framework, and its logging framework also uses Logback. So, why can we use Logback directly without manually importing its package?
By examining Spring Boot’s Maven dependency tree, we can see that the spring-boot-starter module includes the spring-boot-starter-logging module, and the spring-boot-starter-logging module automatically imports logback-classic (which includes the SLF4J and Logback logging frameworks) and some adaptors for SLF4J. Among them, log4j-to-slf4j is used to bridge Log4j2 API to SLF4J, and jul-to-slf4j is used to bridge java.util.logging API to SLF4J:
Next, I will discuss logging configuration and the problems of logging recording with a few real-world examples, and use Logback as an example to review common logging configurations.
Why is my log duplicated? #
Duplicated logging is very common in business scenarios, which not only causes unnecessary trouble for log viewing and statistics, but also increases the burden on disk and log collection systems. Next, I will share two cases of duplicate logging and help you understand the basic structure of Logback configuration.
The first case is that logger configuration inheritance leads to duplicate logging. First, define a method to implement logging for debug, info, warn, and error levels:
@Log4j2
@RequestMapping("logging")
@RestController
public class LoggingController {
@GetMapping("log")
public void log() {
log.debug("debug");
log.info("info");
log.warn("warn");
log.error("error");
}
}
Then, use the following Logback configuration:
Line 11 and 12 set the global log level to INFO, and the log output uses the CONSOLE Appender.
Lines 3 to 7 define the CONSOLE Appender as ConsoleAppender, which means that the log will be output to the console (System.out/System.err); then, through PatternLayout, the output format of the log is defined. For various uses of formatting strings, you can further refer to the official documentation.
Lines 8 to 10 implement a Logger configuration, setting the log level of the application package to DEBUG, and also using the CONSOLE Appender for log output.
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
</layout>
</appender>
<logger name="org.geekbang.time.commonmistakes.logging" level="DEBUG">
<appender-ref ref="CONSOLE"/>
</logger>
<root level="INFO">
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
This configuration seems fine, but after executing the method, the problem of duplicated logging occurs:
From lines 9 and 12 of the configuration file, we can see that the CONSOLE Appender is mounted on two Loggers at the same time: the one we defined and the root Logger. Since the one we defined inherits from the root Logger, the same log will be recorded by both loggers and sent to the root logger, resulting in duplicated logging in the application package logs.
Later, I learned that the intention of this configuration was to implement a custom logger configuration that temporarily enables DEBUG-level log recording within the application. In fact, there is no need to mount the Appender repeatedly. It can be removed by removing the Appender mounted under .
</filter>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<appender name="ERROR_FILE" class="ch.qos.logback.core.FileAppender">
<File>${logDir}/${app.name}_error.log</File>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>WARN</level>
</filter>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="INFO_FILE"/>
<appender-ref ref="ERROR_FILE"/>
</root>
</configuration>
This configuration file is quite long. Let’s break it down section by section:
Lines 31 to 35 define the root element, which references three appenders.
Lines 5 to 9 define the first ConsoleAppender, which logs all messages to the console.
Lines 10 to 19 define a FileAppender, used to log messages to a file. It specifies the file name, log format, and encoding. The most important part is the LevelFilter defined on lines 12 to 14, which filters the log messages based on their level. In this case, it is set to INFO, meaning the _info.log file will only contain log messages of the INFO level.
Lines 20 to 30 define a similar FileAppender, but with a ThresholdFilter that filters based on the log level. In this case, it is set to WARN, meaning the _error.log file will only contain log messages of the WARN level and above.
Let’s run a test program:
As you can see, the _info.log file contains log messages of INFO, WARN, and ERROR levels, which is not what we expect. The error.log file contains log messages of WARN and ERROR levels. This results in duplicate log collection.
You may wonder why such an obvious log duplication issue was not discovered earlier. Some companies use automated ELK solutions to collect logs, where logs are output to both the console and files. Developers usually don’t pay much attention to the log messages recorded in files during local testing. Moreover, in testing and production environments, developers may not have access to the servers, making it difficult to discover log duplication issues in the original log files.
To analyze the cause of log duplication, let’s review the configuration of ThresholdFilter and LevelFilter.
Analyzing the source code of ThresholdFilter, we can see that it returns NEUTRAL if the log level is greater than or equal to the configured level. This means it will continue to call the next filter in the filter chain. Otherwise, it returns DENY to directly reject logging the message:
public class ThresholdFilter extends Filter<ILoggingEvent> {
public FilterReply decide(ILoggingEvent event) {
if (!isStarted()) {
return FilterReply.NEUTRAL;
}
if (event.getLevel().isGreaterOrEqual(level)) {
return FilterReply.NEUTRAL;
} else {
return FilterReply.DENY;
}
}
}
In this case, setting the ThresholdFilter to WARN will record log messages of the WARN level and above.
LevelFilter is used to compare log levels and perform corresponding actions. If there is a match, it calls the onMatch defined action, which by default means passing it to the next filter in the filter chain (defined in the AbstractMatcherFilter base class). Otherwise, it calls the onMismatch defined action, which by default is also to pass it to the next filter.
public class LevelFilter extends AbstractMatcherFilter<ILoggingEvent> {
public FilterReply decide(ILoggingEvent event) {
if (!isStarted()) {
return FilterReply.NEUTRAL;
}
if (event.getLevel().equals(level)) {
return onMatch;
} else {
return onMismatch;
}
}
}
public abstract class AbstractMatcherFilter<E> extends Filter<E> {
protected FilterReply onMatch = FilterReply.NEUTRAL;
protected FilterReply onMismatch = FilterReply.NEUTRAL;
}
Unlike ThresholdFilter, LevelFilter cannot function properly if only the level is configured. Since no onMatch and onMismatch properties are configured, the filter becomes useless and all log messages above INFO level will be recorded.
Once we have identified the issue, the solution is clear. We need to set the onMatch property of the LevelFilter to ACCEPT, indicating that log messages of the INFO level should be accepted. And we need to set the onMismatch property to DENY, indicating that no log messages other than INFO level should be recorded:
<appender name="INFO_FILE" class="ch.qos.logback.core.FileAppender">
<File>${logDir}/${app.name}_info.log</File>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
...
</appender>
With this modification, the _info.log file will only contain log messages of the INFO level, and the log duplication issue will be resolved.
Pitfalls of using asynchronous logging to improve performance #
After mastering the method of outputting logs to a file, our next challenge is to avoid logging becoming a performance bottleneck for our application. This can help us solve the problem of how to log efficiently when disk IO performance is poor (such as with mechanical hard drives) and the log volume is large.
Let’s first test the performance issue of logging. The following log configuration is defined, with two appenders:
FILEis a FileAppender used to log all logs.CONSOLEis a ConsoleAppender used to log logs with atimemarker.
<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
</encoder>
</appender>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n</pattern>
</layout>
<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
<evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
<marker>time</marker>
</evaluator>
<onMismatch>DENY</onMismatch>
<onMatch>ACCEPT</onMatch>
</filter>
</appender>
<root level="INFO">
<appender-ref ref="FILE"/>
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
You may have noticed that in this code snippet there is an EvaluatorFilter, which is used to determine if a log entry meets certain conditions.
In the subsequent test code, we will output a large number of logs to a file. Since the log file will be very large, it will be difficult to find the log entries mixed in with the performance test results. Therefore, we use the EvaluatorFilter to filter the logs based on a marker and output the filtered logs to the console separately. In this case, we have marked the log entry that outputs the test result with the time marker.
Using markers and EvaluatorFilter together is a good technique for filtering logs based on tags.
In the following test code, we will record a large number of logs, each log entry containing 1MB of simulated data, and finally record a log entry that measures the execution time of the method using the time marker:
@GetMapping("performance")
public void performance(@RequestParam(name = "count", defaultValue = "1000") int count) {
long begin = System.currentTimeMillis();
String payload = IntStream.rangeClosed(1, 1000000)
.mapToObj(__ -> "a")
.collect(Collectors.joining("")) + UUID.randomUUID().toString();
IntStream.rangeClosed(1, count).forEach(i -> log.info("{} {}", i, payload));
Marker timeMarker = MarkerFactory.getMarker("time");
log.info(timeMarker, "took {} ms", System.currentTimeMillis() - begin);
}
After executing the program, we can see that the execution time for recording 1000 log entries and 10000 log entries is 6.3 seconds and 44.5 seconds, respectively.
For code that only logs to a file, this is quite slow. To analyze the reasons for this, we need to examine the source code of FileAppender.
FileAppender inherits from OutputStreamAppender. By looking at lines 30 to 33 of the OutputStreamAppender source code, we can see that when appending logs, the logs are directly written to the outputstream, which means that logging is done synchronously:
public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
private OutputStream outputStream;
boolean immediateFlush = true;
@Override
protected void append(E eventObject) {
if (!isStarted()) {
return;
}
subAppend(eventObject);
}
protected void subAppend(E event) {
if (!isStarted()) {
return;
}
try {
// Encode the LoggingEvent
byte[] byteArray = this.encoder.encode(event);
// Write the bytes to the stream
writeBytes(byteArray);
} catch (IOException ioe) {
// ...
}
}
private void writeBytes(byte[] byteArray) throws IOException {
if(byteArray == null || byteArray.length == 0)
return;
lock.lock();
try {
// The OutputStream is actually a ResilientFileOutputStream, which uses a buffered BufferedOutputStream internally
this.outputStream.write(byteArray);
if (immediateFlush) {
this.outputStream.flush(); // Flush to the OS
}
} finally {
lock.unlock();
}
}
}
By analyzing this, we can understand why it takes so long to write a large number of logs. So, is there a way to log a large number of logs without significantly affecting the execution time of the business logic and the throughput?
Of course there is. We can use Logback’s AsyncAppender to achieve asynchronous log recording. AsyncAppender is similar to the decorator pattern, which means that it adds new functionality to a class without changing its original basic functionality. In this way, we can attach the AsyncAppender to other appenders and make them asynchronous.
To implement asynchronous logging to the file, define an asynchronous appender ASYNCFILE that wraps the synchronous file appender for logging to a file:
<appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE"/>
</appender>
<root level="INFO">
<appender-ref ref="ASYNCFILE"/>
<appender-ref ref="CONSOLE"/>
</root>
After testing, we can see that the execution time for recording 1000 log entries and 10000 log entries is 735 milliseconds and 668 milliseconds, respectively.
The performance is unexpectedly good. Do you think there is any problem with this? Is asynchronous logging really so magical and all-powerful? Of course not, because not all logs are recorded this way. I have encountered many pitfalls with AsyncAppender in the past, which can be categorized into three types:
- Exhausting memory when logging asynchronously
- Losing logs when logging asynchronously
- Blocking when logging asynchronously
To explain these three pitfalls, I will simulate a scenario of slow log recording. First, customize a class MySlowAppender that extends ConsoleAppender to log to the console, and sleep for 1 second when writing logs.
public class MySlowAppender extends ConsoleAppender {
@Override
protected void subAppend(Object event) {
// ...
}
}
Try { // Simulate slow logs TimeUnit.MILLISECONDS.sleep(1); } catch (InterruptedException e) { e.printStackTrace(); }
super.subAppend(event); } }
Then, use the AsyncAppender in the configuration file to wrap MySlowAppender for asynchronous logging:
$$$
[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%-5level] [%logger{40}:%line] - %msg%n
Define a test code that logs a certain number of times in a loop, and finally output the method execution time:
$$$ @GetMapping(“manylog”) public void manylog(@RequestParam(name = “count”, defaultValue = “1000”) int count) {
long begin = System.currentTimeMillis(); IntStream.rangeClosed(1, count).forEach(i -> log.info(“log-{}”, i)); System.out.println(“took " + (System.currentTimeMillis() - begin) + " ms”); } $$$
After executing the method, it is found that the time is short but there is log loss: we need to log 1000 logs, and only 215 logs can be searched in the console, and the line number of the log becomes a question mark.
The reason for this problem is that the AsyncAppender provides some configuration parameters, which we did not use. Let’s analyze it with the relevant source code:
includeCallerData is used to control whether to collect caller data. The default is false, in which case information such as method line number and method name cannot be displayed (source code lines 2 and 7 to 11).
queueSize is used to control the size of the blocking queue, using the ArrayBlockingQueue blocking queue (source code lines 15 to 17), the default size is 256, that is, up to 256 logs are stored in memory.
discardingThreshold is a threshold for discarding logs, mainly to prevent blocking after the queue is full. By default, when the remaining capacity of the queue is less than 20% of the queue length, TRACE, DEBUG, and INFO level logs will be discarded. (See lines 3 to 6, 18 to 19, 26 to 27, 33 to 34, and 40 to 42 of the source code)
neverBlock is used to control whether the data is directly discarded when the queue is full, without blocking and waiting. The default is false (source code lines 44 to 68). Here, we need to pay attention to the difference between the offer method and the put method. When the queue is full, the offer method does not block, while the put method blocks; when neverBlock is true, the offer method is used. public class AsyncAppender extends AsyncAppenderBase {
boolean includeCallerData = false; // Whether to collect caller data protected boolean isDiscardable(ILoggingEvent event) { Level level = event.getLevel(); return level.toInt() <= Level.INFO_INT; // Discard logs with <= INFO level }
protected void preprocess(ILoggingEvent eventObject) { eventObject.prepareForDeferredProcessing(); if (includeCallerData) eventObject.getCallerData(); } }
public class AsyncAppenderBase extends UnsynchronizedAppenderBase implements AppenderAttachable {
BlockingQueue<E> blockingQueue; // The key to asynchronous logging, a blocking queue
public static final int DEFAULT_QUEUE_SIZE = 256; // Default queue size
int queueSize = DEFAULT_QUEUE_SIZE;
static final int UNDEFINED = -1;
int discardingThreshold = UNDEFINED;
boolean neverBlock = false; // Determines whether to discard data directly when the queue is full, without blocking and waiting
@Override
public void start() {
...
blockingQueue = new ArrayBlockingQueue<E>(queueSize);
if (discardingThreshold == UNDEFINED)
discardingThreshold = queueSize / 5; // The default discard threshold is 20% of the queue length, see isQueueBelowDiscardingThreshold method
...
}
@Override
protected void append(E eventObject) {
if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { // Determine whether the data can be discarded
return;
}
preprocess(eventObject);
put(eventObject);
}
private boolean isQueueBelowDiscardingThreshold() {
return (blockingQueue.remainingCapacity() < discardingThreshold);
}
private void put(E eventObject) {
if (neverBlock) { // Use non-blocking offer or blocking put method depending on the neverBlock value
blockingQueue.offer(eventObject);
} else {
putUninterruptibly(eventObject);
}
}
// Add data to the queue in a blocking manner
private void putUninterruptibly(E eventObject) {
boolean interrupted = false;
try {
while (true) {
try {
blockingQueue.put(eventObject);
break;
} catch (InterruptedException e) {
interrupted = true;
}
}
} finally {
if (interrupted) {
Thread.currentThread().interrupt();
}
}
}
}
Upon seeing that the default queue size is 256 and that logs with a severity level <=INFO are being discarded once the capacity reaches 80%, it is now clear why there are only 215 INFO logs.
Let’s continue to analyze why there are pitfalls in asynchronous log recording.
Setting the queueSize to an extremely large value could potentially lead to an OutOfMemoryError (OOM).
Setting the queueSize to a relatively small value (especially the default value) and having a discardingThreshold greater than zero (or using the default value) will result in discarding <=INFO logs when the remaining capacity of the queue falls below the discardingThreshold. There are two pitfalls here. First, due to the presence of the discardingThreshold, setting the queueSize can easily lead to pitfalls. For example, even if the maximum log concurrency is 1000, setting the queueSize to 1000 will still result in log loss. Second, the discardingThreshold parameter can be confusing. It is not a percentage, but rather a number of logs. For a queue with a total capacity of 10000, if you want to discard logs when the remaining capacity is less than 1000 logs, it needs to be configured as 1000.
neverBlock is set to false by default, meaning that blocking is possible. If the discardingThreshold is set to 0, the program will block when the queue is full. If the discardingThreshold is not 0, only <=INFO logs will be discarded, but the program will still block when there are a large number of error logs.
It can be seen that the queueSize, discardingThreshold, and neverBlock parameters are closely related. They must be set and chosen according to the needs. The priorities can be performance first or no data loss first:
If performance is the absolute priority, set neverBlock to true to never block.
If ensuring no data loss is the absolute priority, set the discardingThreshold to 0 so that even <=INFO level logs won’t be discarded. However, it is better to set a larger queueSize, as the default queueSize is obviously too small and prone to blocking.
If you want to balance both, you can discard unimportant logs, set a larger queueSize, and then set a reasonable discardingThreshold.
These are the two most common pitfalls in log configuration. Next, let’s take a look at another pitfall in log recording itself.
Do we still need to judge the log level when using log placeholders? #
I don’t know if you have heard: SLF4J’s {} placeholder syntax only retrieves the actual parameters when logging, thus solving the performance issue of log data retrieval. Do you think this statement is true?
To verify this, let’s write a test code: there is a slowString method that takes 1 second to return the result:
private String slowString(String s) {
System.out.println("slowString called via " + s);
try {
TimeUnit.SECONDS.sleep(1);
} catch (InterruptedException e) {
}
return "OK";
}
If we try to log DEBUG logs and set to only log messages with a level of >=INFO, will the program also take 1 second? We will use three methods to test:
- Log slowString by concatenating strings;
- Log slowString using placeholders;
- Check if DEBUG log level is enabled before logging.
StopWatch stopWatch = new StopWatch();
stopWatch.start("debug1");
log.debug("debug1:" + slowString("debug1"));
stopWatch.stop();
stopWatch.start("debug2");
log.debug("debug2:{}", slowString("debug2"));
stopWatch.stop();
stopWatch.start("debug3");
if (log.isDebugEnabled())
log.debug("debug3:{}", slowString("debug3"));
stopWatch.stop();
As seen in the code, the first two methods both call the slowString method, so they both take 1 second:
The method of logging slowString using placeholders also takes 1 second. This is because although this method allows us to pass in objects without concatenating strings, it still delays (or saves) the time of calling the object’s toString() method and string concatenation if the log is not recorded.
In this case, unless the log level is checked in advance, the slowString method will be called without a doubt. Going back to the question raised earlier, using the {} placeholder syntax does not solve the performance issue of log data retrieval by delaying parameter value retrieval.
In addition to checking the log level in advance, we can also use lambda expressions to delay parameter content retrieval. However, SLF4J API does not currently support lambdas, so we need to use the Log4j2 logging API and replace Lombok’s @Slf4j annotation with @Log4j2 annotation in order to provide a lambda expression as the method for supplying parameter data:
@Log4j2
public class LoggingController {
...
log.debug("debug4:{}", ()->slowString("debug4"));
When calling the debug method like this, the signature is Supplier and the parameters will only be retrieved when the log needs to be recorded:
void debug(String message, Supplier<?>... paramSuppliers);
public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message,
final Supplier<?>... paramSuppliers) {
if (isEnabled(level, marker, message)) {
logMessage(fqcn, level, marker, message, paramSuppliers);
}
}
protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message,
final Supplier<?>... paramSuppliers) {
final Message msg = messageFactory.newMessage(message, LambdaUtil.getAll(paramSuppliers));
logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
}
After making the modification, run the test again, and you will see that this time debug4 does not call the slowString method:
In fact, we only switched to the Log4j2 API, and the actual log recording is still done by the Logback framework. Yes, this is one of the benefits of SLF4J’s adaptation.
Key Takeaways #
I will summarize the pitfalls of logging into two aspects: framework configuration and logging itself.
There are many logging frameworks in Java, and SLF4J provides a unified way to use these frameworks for logging. When using SLF4J, we need to understand its bridge API and binding modules. If there is an error message related to SLF4J during program startup, it is likely due to configuration issues. You can use the dependency:tree command in Maven to analyze the dependency relationships.
Logback is the most commonly used logging framework in Java, and its configuration can be complex. You can refer to the official documentation for configuration details on Appenders, Layouts, and Filters. Remember not to copy configurations from other sources indiscriminately to avoid errors or configurations that don’t meet your current needs.
Using asynchronous logging to solve performance issues is a trade-off between space and time. However, space is limited. When the space is full, you need to consider whether to block and wait or discard logs. If you prioritize not discarding important logs, choose to block and wait. If you want to avoid program blocking due to logging, you need to discard logs.
Lastly, I want to emphasize that the parameterized logging provided by logging frameworks cannot completely replace the judgment of log levels. If you have a large amount of logging and obtaining log parameters is costly, you need to consider the log level accordingly to avoid the overhead of getting log parameters when logging is disabled.
I have put all the code used today on GitHub, you can click on this link to view it.
Reflection and Discussion #
In the case study in the first section, we store logs with the INFO level in _info.log and logs with the WARN and ERROR levels in _error.log. If we now want to store logs with the INFO and WARN levels in _info.log, and logs with the ERROR level in _error.log, how should we configure Logback?
For file logging in production-grade projects, it is necessary to split and archive logs based on time and date to avoid individual files from becoming too large. At the same time, a certain number of days’ worth of historical logs should be retained. Do you know how to configure this? You can find the answer in the official documentation.
Have you encountered any other pitfalls related to log recording and configuration? I’m Zhu Ye. Feel free to leave a comment in the comment section to share your experiences. You are also welcome to share this article with your friends or colleagues for further discussion.