User Roman B.
Roman B.
Level 35
Kharkiv

Logging: what, how, where, and with what?

Published in the Java Developer group
Hello everyone in the CodeGym community! Logging: what, how, where, and with what? - 1 Today let's talk about logging:
  1. What it is, why it exists, when you should use it, when you should avoid it.
  2. What logging implementations are available in Java, and what you should do with all these logging options.
  3. And log levels. We'll discuss what appender is and how to configure it correctly.
  4. Logging nodes and how to configure them correctly so that everything works the way we want.
This material is intended for a wide audience. It will be clear to anyone just getting to know Java, as well as people who are already working but have only explored logger.info("log something"); Let's go!

Why do you need logging?

Let's look at some real cases where logging can solve a problem. Here is an example from my work. There are points where an application integrates with other services. I use logging at these points to establish a kind of "alibi": if the integration isn't working, then it becomes easy to figure out which side has the problem. It is also desirable to log important information stored in a database. For example, the creation of an admin user. This is precisely the sort of thing that would be good to log.

Tools for logging in Java

Among the well-known logging solutions in Java, we can highlight the following:
  • Log4j
  • JUL — java.util.logging
  • JCL — Jakarta Commons Logging
  • Logback
  • SLF4J — Simple Logging Facade for Java
We will provide an overview of each of them. Then we'll take a slf4j-log4j binding as the basis of a practical discussion. This may seem strange now, but don't worry: by the end of the article, everything will be clear.

System.err.println

In the beginning, there was System.err.println (displaying log entries on the console). Even today, this technique is used to quickly a log when debugging. Of course, there are no settings to discuss here, so just remember this method and we'll move on.

Log4j

This is a complete solution that developers created out of necessity. The result is a really interesting tool that you can use. Due to various circumstances, this solution did not end up in the JDK, a fact that greatly upset the entire community. Log4j has configuration options that let you enable logging in the com.example.type package and turn it off in the com.example.type.generic subpackage. This makes it possible to quickly exclude code that does not need to be logged. It is important to note here that there are two versions of Log4j: 1.2.x and 2.x.x, and they are incompatible with each other. Log4j added the concepts of appender (a tool used to write logs) and layout (log formatting). This lets you log only what you need and log it just how you need it. We'll talk more about appender a little later.

JUL — java.util.logging

One of the key benefits of this solution is that JUL is included in the JDK (Java Development Kit). Unfortunately, when it was developed, its creators did not base it on the popular Log4j utility, but rather a solution from IBM. That decision has had consequences. The reality is that nobody uses JUL now. The log levels in JUL differ from what Logback, Log4j, and Slf4j have. This makes it harder for them to understand one another. Creating a logger is more or less similar. To do this, you need to do an import:

java.util.logging.Logger log = java.util.logging.Logger.getLogger(LoggingJul.class.getName());
The class name is passed, so we know where our logging will come from. Starting with Java 8, you can pass Supplier<String>. This helps us read and create a line only when we really need it, rather than every time, as was previously the case. Only with the release of Java 8 did developers finally solve important problems and made JUL truly usable. Namely, methods with a Supplier<String> msgSupplier parameter, as shown below:

public void info(Supplier<String> msgSupplier) {
   log(Level.INFO, msgSupplier);
}

JCL — Jakarta Commons Logging

Because there was no industry standard regarding logging for a long time and many people created their own custom loggers, the decision was made to release JCL, a general wrapper that could be used on top of others. Why? Sometimes dependencies added to the project used a different logger than the one in the project. Because of this, they were added to the project as transitive dependencies, and this created real problems when trying to put it all together. Unfortunately, the wrapper was not very functional and didn't add anything. It would probably be convenient if everyone used JCL. But that's not what happened, so using JCL isn't the best idea at the moment.

Logback

The open-source path is thorny... The same developer that wrote Log4j also wrote Logback as a successor logging framework. It was based on the same idea as Log4j. The differences in Logback are:
  • improved performance
  • added native support for Slf4j
  • expanded filtering options
By default, Logback does not require any configuration, and records all events at DEBUG level and higher. If you need some customization, you can get achieve it through an XML configuration:

<configuration> 
    <appender name="FILE" class="ch.qos.logback.core.FileAppender"> 
        <file>app.log</file> 
        <encoder> 
            <pattern>%d{HH:mm:ss,SSS} %-5p [%c] - %m%n</pattern> 
        </encoder> 
    </appender> 
    <logger name="org.hibernate.SQL" level="DEBUG" /> 
    <logger name="org.hibernate.type.descriptor.sql" level="TRACE" /> 
    <root level="info"> 
        <appender-ref ref="FILE" /> 
    </root> 
</configuration>

SLF4J — Simple Logging Facade for Java

Sometime in 2006, one of Log4j's founding fathers left the project and created Slf4j (Simple Logging Facade for Java), a wrapper for Log4j, JUL, common-logging, and Logback. As you can see, we've advanced to the point of creating a wrapper over a wrapper... In this case, it is divided into two parts: An API that is used in the application, and an implementation that is added with separate dependencies for each type of logging. For example, slf4j-log4j12.jar and slf4j-jdk14.jar. You need to hook up the correct implementation and that's it: your entire project will use it. Slf4j supports all the latest features, such as formatting strings for logging. Previously, there was such a problem. Let's say we create a log entry like this:

log.debug("User " + user + " connected from " + request.getRemoteAddr());
Due to the concatenation operator, the user object silently becomes a string thanks to user.toString(). This takes time and slows down the system. And that may be OK if we're debugging the application. We start to encounter problems if the log level for this class is INFO or higher. In other words, we shouldn't write this log entry (for INFO or higher), and we shouldn't use string concatenation. In theory, the logging library itself should address this. As it happens, this turned out to be the biggest problem in the first version of Log4j. It didn't deliver a decent solution, but instead suggested doing something like this:

if (log.isDebugEnabled()) {
    log.debug("User " + user + " connected from " + request.getRemoteAddr());
}
That is, instead of one line of code for logging, they suggested writing 3! Logging should minimize code changes, and the three lines clearly violate that general approach. Slf4j had no compatibility issues with the JDK and API, so a nice solution immediately emerged:

log.debug("User {} connected from {}", user, request.getRemoteAddr());
where {} denotes placeholders for the arguments passed to the method. That is, the first {} corresponds to user, and the second {} corresponds to request.getRemoteAddr(). By doing it this way, we will perform string concatenation only if the log level requires us to write the log entry. After that, Sjf4j began to rapidly grow in popularity. At present, it is the best solution. Accordingly, let's take a look at logging using a slf4j-log4j12 binding.

What needs to be logged

Of course, you should not log everything. This is often not necessary and sometimes even dangerous. For example, if you log someone's personal data and it somehow gets leaked, there will be real problems, especially in projects focused on Western markets. But there are also things that you should definitely log:
  1. Start/end of the application. We need to know whether the application really started and ended as expected.
  2. Security issues. Here it would be good to log attempts at guessing someone's password, instances when admins sign in, etc.
  3. Certain application states. For example, the transition from one state to another in a business process.
  4. Certain debug information along with the corresponding log level.
  5. Certain SQL scripts. There are real-world cases when this is necessary. But again, by skillfully adjusting the log levels, you can achieve excellent results.
  6. Running threads can be logged when verifying that things are working correctly.

Popular errors in logging

There are many nuances here, but we will make special mention of a few common mistakes:
  1. Excessive logging. You shouldn't log every step that could theoretically be important. Here a good rule of thumb: Logs should not exceed 10% of the load. Otherwise, there will be performance problems.
  2. Logging all data into one file. At some point, this will make it very difficult to read/write the log, not to mention the fact that certain systems have limits on file size.
  3. Using incorrect log levels. Each log level has clear boundaries, and they should be respected. If a boundary is unclear, you can come to an agreement about which level to use.

Log levels

x: Visible
FATAL ERROR WARN INFO DEBUG TRACE ALL
OFF
FATAL x
ERROR x x
WARN x x x
INFO x x x x
DEBUG x x x x x
TRACE x x x x x x
ALL x x x x x x x
What are log levels? In order to somehow create a hierarchy of log entries, certain conventions and delimitations are necessary. This is why log levels were introduced. The level is set in the application. If an entry is below a specified level, then it is not logged. For example, we have logs that we use when debugging the application. During normal operation (when the application is used for its intended purpose), such logs are not needed. Therefore, the log level is higher than for debugging. Let's look at log levels using Log4j. Apart from JUL, other solutions use the same log levels. Here they are in decreasing order:
  • OFF: No log entries are recorded; everything is ignored.
  • FATAL: An error that prevents the application from continuing to run. For example, "JVM out of memory error".
  • ERROR: Errors at this level indicate problems that need to be resolved. The error does not stop the application as a whole. Other requests may work correctly.
  • WARN: Log entries that represent a warning. Something unexpected happened, but the system was able to cope and fulfilled the request
  • INFO: Log entries that indicate important actions in the application. These are not errors or warnings. They are expected system events.
  • DEBUG: Logs entries need to debug the application. For ensuring that the application does exactly what is expected, or for describing the actions taken by the application, i.e. "Entered method1".
  • TRACE: Lower-priority log entries for debugging. The lowest log level.
  • ALL: A log level for writing all of the application's log entries.
In the INFO log level is enabled somewhere in the application, then the entries for every level will be logged, from INFO to FATAL. If the FATAL log level is set, only log entries with that level will be written.

Logging and sending logs: Appender

Let's consider how all this works when we use Log4j, which provides ample opportunities for writing/sending logs:
  • to write to a file — DailyRollingFileAppender
  • to write information to the console — ConsoleAppender
  • to write logs to a database — JDBCAppender
  • to manage sending logs over TCP/IP — TelnetAppender
  • for ensuring that logging does not negatively impact performance — AsyncAppender
There are a few more implementations: a complete list is available here. By the way, if the appender you need doesn't exist, that's no problem. You can write your own appender by implementing the Appender interface, which Log4j supports. Logging: what, how, where, and with what? - 2

Logging nodes

For demonstration purposes, we will use a Slf4j interface, with an implementation from Log4j. Creating a logger is very simple: in a class named MainDemo, which will do some logging, we need to add the following:

org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(MainDemo.class);
This will create a logger for us. To make a log entry, there are several available methods whose names reflect which log level will be used. For example:

logger.trace("Method 1 started with argument={}", argument);
logger.debug("Database updated with script = {}", script);
logger.info("Application has started on port = {}", port);
logger.warn("Log4j didn't find the log4j.properties file. Please fix this.");
logger.error("Connection refused to host = {}", host);
Although we are passing the class, the final name is the class's full name, including packages. This is done so that later you can divide the logging into nodes and configure the logging level and appender for each node. For example, the logger was created in the com.github.romankh3.logginglecture.MainDemo class. The name provides the basis for creating a hierarchy of logging nodes. The main node is top-level RootLogger. This is the node that receives all log entries for the entire application. The remaining nodes can be depicted as shown below: Logging: what, how, where, and with what? - 3Appenders are configured for specific logging nodes. Now we're going to look at the log4j.properties file to see an example of how to configure them.

A step-by-step guide to the log4j.properties file

We'll set everything up one step at a time and see what's possible:

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
This line says that we are registering the CONSOLE appender, which uses the org.apache.log4j.ConsoleAppender implementation. This appender writes information to the console. Next, we register another appender. This one will write to a file:

log4j.appender.FILE=org.apache.log4j.RollingFileAppender
It is important to note that the appenders themselves still need to be configured. Once we have registered our appenders, we can determine which log levels and which appenders will be used at the nodes.

log4j.rootLogger=DEBUG, CONSOLE, FILE

  • log4j.rootLogger means we are configuring the root node, which contains all log entries
  • The first word after the equals sign indicates the minimum log level to write (in our case, it is DEBUG)
  • Following the comma, we indicate all the appenders to be used.
To configure a more specific logging node, you would use an entry like this:

log4j.logger.com.github.romankh3.logginglecture=TRACE, OWN, CONSOLE
where log4j.logger. is used to reference a specific node. In our case, com.github.romankh3.logginglecture. Now let's talk about configuring the CONSOLE appender:

# CONSOLE appender customization
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.threshold=DEBUG
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=[%-5p] : %c:%L : %m%n
Here we see that it is possible to set the specific level at which the appender will start working. Here's an example of what actually happens: suppose a message with the INFO level is received by the logging node and passed to the appender assigned to it. If the appender's threshold is set to WARN, then it receives the log entry but does nothing with it. Next, we need to decide which layout the message will use. I use PatternLayout in the example, but there are many other options. We won't cover them in this article. Example of configuring the FILE appender:

# File appender customization
log4j.appender.FILE=org.apache.log4j.RollingFileAppender
log4j.appender.FILE.File=./target/logging/logging.log
log4j.appender.FILE.MaxFileSize=1MB
log4j.appender.FILE.threshold=DEBUG
log4j.appender.FILE.MaxBackupIndex=2
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=[ %-5p] - %c:%L - %m%n
You can configure the specific file to which log entries will be written, as can be seen from this line:

log4j.appender.FILE.File=./target/logging/logging.log
The entry is written to the logging.log file. To avoid problems with the file size, you can configure the maximum, which in this case is 1MB. MaxBackupIndex indicates how many such log files there will be. If we need to create more files than this, then the first file will be deleted. To look at a real example where logging is configured, you can go to the public repository on GitHub.

Reinforce what we've discussed

Try on your own to do everything we have described:
  • Create your own project similar to our example above.
  • If you know how to use Maven, use it. If not, then read this tutorial, which describes how to to connect the library.

In summary

  1. We talked about the logging solutions that exist in Java.
  2. Almost all of the well-known logging libraries were written by one person :D
  3. We learned what should and should not be logged.
  4. We figured out log levels.
  5. We were introduced to logging nodes.
  6. We looked at what an appender is and what it is for.
  7. We created a log4j.proterties file step by step.

Additional materials

  1. CodeGym: Logger lesson
  2. Weekly Geekly: Java logging. Hello world
  3. Coding Horror: The Problem With Logging
  4. YouTube: Understanding Java Logging Hell - The Basics. Java Logging Hell & How to stay out of it
  5. Log4j: Appender
  6. Log4j: Layout
Also see my other article:
Comments
TO VIEW ALL COMMENTS OR TO MAKE A COMMENT,
GO TO FULL VERSION