Java is used by at least 7.6 Million developers worldwide. Java logging has been a staple of the Java platform since day one, boasting extensive, resourceful documentation and rich API’s. The cornerstone of monitoring your application is efficient and widespread logging. At Coralogix, we know the importance of modern log monitoring software.
There are certain discrepancies between logging within monolithic architectures vs modern microservice approaches. The distributed nature of microservices means an inherent increase in the amount of log data required, making serialization and centralization of logs trickier in comparison to its monolith counterpart. With such considerations in mind, we will be delving into the best logging practices for Java, and highlighting the importance and reasoning of the best practices we are implementing.
How we will approach Java Logging
We will start by exploring a Java facade called slf4j, which will allow us to plug in any Java logging framework at runtime. This is massively advantageous when working in a legacy codebase, or looking to use different logging mechanisms for different areas of your system. Apart from this, slf4j allows you to easily co-implement logging libraries, move from one framework to another, manage dependencies, or even profiling, which is analyzing system performance through the use of stopwatch mechanisms.
This will lead us into some theoretical footing on some of the best practices we will be implementing. It will be important to understand why we are doing the things we will do, and why this will lead us to optimal practices when it comes to maintaining a system or application.
We will then get stuck into building a simple Java application and injecting log4j, a Java logging utility, all within our slf4j abstraction. By the end of the tutorial, you should be able to effectively implement the best practices when it comes to logging in Java, as well as some high-performance logging contexts.
Prerequisites for Java Logging
In this tutorial, we will require:
- Java Version 11+
- slf4j Version 1.7.30+
- log4j Version 2+
- Maven
Abstractions in SLF4J
By providing a logging API for injecting any runtime Java logging frameworks, slf4j plays an important role in reducing the coupling between your application and your logging framework. By moving towards a more decoupled approach, we reduce interdependence between components, giving us more flexibility when it comes to maintaining our application.
To illustrate my point a little further, this is the relationship slf4j will have within our example application that we will build:
The abstraction that slf4j offers us should be visible due to the way it fits into our application architecture. With such, we can migrate to any logging framework at runtime without being held down by single dependency. If we had opted to not use a logging abstraction like slf4j, but rather a framework from the get-go, we would then be limited to that particular framework barring code refactoring. This would definitely not be a best practice.
Without further ado, let’s get into some practical examples of how slf4j works, and we will begin to understand some of the advantages it offers us.
Setting up our Java Logging App
Create a simple maven application. We won’t go into too much detail here, since there are a thousand tutorials online. You’ll need a simple application with a pom.xml ready-to-go. Once you have this, you should add the SLF4J API and SLF4J Simple dependencies to your pom file. Then, create a java file within our package folder, and name it MyLogger.java. Paste in the following code:
package bestPractices;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MyLogger {
public static void main(String[] args) {
//Creating our custom Logger
Logger logger = LoggerFactory.getLogger("FirstLogger");
//Some simple outputs
logger.info("Simply an update");
logger.error("Example of an error");
}
}
If we run the file, we should get the following:
[main] INFO FirstLogger - Simply an update
[main] ERROR FirstLogger - Example of an error
Here we are using the ‘info’ and ‘error’ severity levels, as of course slf4j offers different severity levels according to the type of message you would like to log.
log4j within the slf4j interface
Now that we have a simple example of logging using slf4j, we can get into adding log4j. log4j is a fast and flexible logging framework, offering thread-safe, run-time behavior configuration. By using log4j under the slf4j abstraction hood, we are able to seamlessly configure our logging utility at runtime, should we, for example, want to swap to a different logging framework.
We need to download the binding for using log4j and slf4j together. Remove the slf4j-simple dependency from your POM and add the following snippet:
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
<version>1.7.30</version>
<scope>test</scope>
</dependency>
We also need to add one more dependency, log4j itself. As it stands, we have the adapter to make it work with slf4j, but we also need the jar file for the dependency on its own. To do this, add the following snippet to your POM file:
<dependency>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
<version>1.2.17</version>
</dependency>
Log4j will help us achieve best practices in the use of its configuration file. With log4j, there is no need to manually modify the vast amounts of logging statements that inevitably pile up within any application. Logging can be quite an arduous task; cutting the amount of time spent manually modifying line by line is a no-brainer. We are going to keep our MyLogger.java the same for now. Within the src directory, create the following structure:
src/main/resources
Within /resources, create a file called log4j.properties. This will keep our runtime configuration for our logging framework. Add the following to log4j.properties:
log4j.rootLogger=DEBUG, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n
These are all the default starting options from the log4j documentation found here. Before running the program again, we need to make sure Eclipse knows to include this file within the classpath. Click Run -> Run Configurations… -> Dependencies -> Classpath Entries -> Click Advanced on the right -> Add Folders. Add the resource folder within src/main/resources.
If we run the file, we should have as output:
2020-08-17 00:52:38,256 [main] INFO FirstLogger - Simply an update
2020-08-17 00:52:38,256 [main] ERROR FirstLogger - Example of an error
The only difference here is that we have added a timestamp on the left. Notice again, how we haven’t touched the main source code. Our formatting is configured and used at runtime.
Java Logging with simple Java Application
Now that we have our logger setup, we can put it to good use. In order to implement best practices, we need something a little bit more complex than the simple example java project we are using. If you have a Java project already set up that you are looking to implement this logging mechanism into, skip this part of the article.
We are just going to create a simple input-based application that allows a user to consult a list of available days of the week for an emergency dentist appointment. This will avoid bringing in any unnecessary dependencies needed for a REST API, but will also allow us to flesh out our logger. The program will prompt the user to input his preferred dentist and when they are available to come in for their appointment. We will be plugging in our logger where necessary to illustrate the best practices.
Replace MyLogger.java with the following:
package bestPractices;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Scanner;
public class MyLogger {
public static void main(String[] args) {
Logger logger = LoggerFactory.getLogger("FirstLogger");
System.out.print("What's your preferred Doctors Name?\n");
Scanner in = new Scanner(System.in);
String dentistName = in.next();
String[] dentist = { "John", "Sally", "Oliver", "Jill" };
String[] days = { "Monday", "Wednesday", "Thursday", "Saturday" };
boolean dentistFound = false;
boolean dayFound = false;
for (String s : dentist) {
if (s.equals(dentistName)) {
System.out.print("Found the dentist!\n");
logger.info("Dentist found: " + dentistName);
dentistFound = true;
break;
}
}
if (dentistFound) {
System.out.println("When would you like to book your emergency appointment?");
String dayPicked = in.next();
for (String p : days) {
if (p.equals(dayPicked)) {
System.out.println("You are booked for " + dayPicked);
logger.info("Appointment booked on " + dayPicked);
dayFound = true;
System.exit(0);
}
}
if (dayFound == false) {
logger.error("Sorry, we are not available on that day.");
logger.info("Exiting application.");
System.exit(0);
}
}
else {
logger.error("Invalid dentist name");
}
logger.info("Exiting application.");
System.exit(0);
}
}
As it stands, MyLogger.java contains a simple flow of user input asking the following:
- The name of the dentist they would like to see.
- The day that they would like to book their emergency appointment, from the available days in the days array.
We have also added some log statements to some of the input validation checks. Let’s run the program with the same inputs: Sally, Saturday.
We should now see the following on the console:
What's your preferred Doctors Name?
INPUT: Sally
Found the dentist!
2020-08-17 03:35:01,006 INFO [main] (MyLogger.java:28) - Dentist found: Sally
When would you like to book your emergency appointment?
INPUT: Saturday
You are booked for Saturday
2020-08-17 03:35:16,009 INFO [main] (MyLogger.java:65) - Appointment booked on Saturday
Perfect. Our logger is working the way it’s supposed to, and we have log updates that are categorized by severity, alongside the timestamp and exact line of code on which the update was executed on. This is an essential starting point – we want to make debugging and maintaining as easy as possible. If an error was to appear, we know exactly what caused it and why.
Adding Context to Your Logs
The example we are using is extremely simplistic. It does, however, resemble a user interaction with a REST API. If we were dealing with user metadata such as sessionID, it would be invaluable to add these to the logs as well.
log4j offers what is known as Mapped Diagnostic Context, or MDC, which allows us to log information that may not necessarily be in the scope of where the logging is actually taking place. If we had hundreds of people using our theoretical service, trying to make bookings and consult availability, it would be extremely difficult to differentiate between two near-identical requests or requests made by the same person over a long period of time. This is where MDC comes in and makes life a whole lot easier.
Navigate to log4j.properties, and modify the following line:
log4j.appender.stdout.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m - %X{sessionId}%n
We are adding %X{sessionId} which will allow us to attach the sessionId to every single log instance.
Navigate to MyLogger.java and import the MDC dependency:
import org.slf4j.MDC;
And add this right underneath public static void main(String[] args) {
String sessionId = "123456";
MDC.put("sessionId", sessionId);
In a real-life example, we would not be manually generating a sessionId. Run the application again, using the following inputs to test out a different console output:
Sally, Sunday
What's your preferred Doctors Name?
INPUT: Sally
Found the dentist!
2020-08-17 03:57:57,100 INFO [main] (MyLogger.java:31) - Dentist found: Sally - 123456
When would you like to book your emergency appointment?
INPUT: Sunday
2020-08-17 03:58:02,767 ERROR [main] (MyLogger.java:75) - Sorry, we are not available on that day. - 123456
2020-08-17 03:58:02,767 INFO [main] (MyLogger.java:76) - Exiting application. - 123456
Great, we have attached our sessionId to every single log instance. This will pay dividends when it comes down to debugging. Instead of searching mindlessly for that particular failure that has caused your entire application to crash, it is easily available in a human-readable format.
So far we have logged to the console. If you would like to write the logged outputs to a file, the official documentation provides easy configuration files to do so. Modify your log4j.properties file to have the following:
log4j.rootLogger=INFO, file
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=log/logging.log
log4j.appender.file.MaxFileSize=10MB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m - %X{sessionId}%n
If we re-run the program with the same inputs, our root directory should have another folder, called log, containing logging.log. The outputs on the console should now only be limited to user input requests from the application.
Simple Use Case with Coralogix
You can make use of log analytics features that are offered by Coralogix. For example, flow anomaly detection can be used to discover a sudden spike in a user ID, or the repeat of a session ID, all indicative of abnormal usage. This opens up the opportunity to create actionable insights for you.
Making Queryable Logs
Now that we have a log file where we are sending our log information, let’s add more value to our logs. A best practice here would be to ensure all of our logged outputs are in JSON form. This makes searching through log files, categorizing data, and maintaining readability a top priority. These are all absolutely essential if you want to maintain control of your codebase.
To transform our logged outputs into JSON objects, we could typically use Logback. There is extensive documentation on how to achieve this with logback and can be found here.
In our application, we can set our log4j.properties file to contain a custom JSON formatter. Modify the file to contain the following:
log4j.rootLogger=INFO, file
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=log/logging.log
log4j.appender.file.MaxFileSize=10MB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.encoding=UTF-8
log4j.appender.file.layout.ConversionPattern={"timestamp":"%d","logUpdate": "%5p [%t] (%F:%L)","status":"%m","sessionID": "%X{sessionId}}%n"
Let us run our program with the following inputs: Sally, Sunday
{"timestamp":"2020-08-17 05:43:02,041","logUpdate": " INFO [main] (MyLogger.java:31)","status":"Dentist found: Sally","sessionID", "123456}
"{"timestamp":"2020-08-17 05:43:05,578","logUpdate": "ERROR [main] (MyLogger.java:75)","status":"Sorry, we are not available on that day.","sessionID" : "123456}
"{"timestamp":"2020-08-17 05:43:05,579","logUpdate": " INFO [main] (Mylogger.java:76)","status":"Exiting application.","sessionID" :"123456"}
Fantastic. We have our logged outputs as JSON objects. This makes our log file easily keyword searchable, as well as allowing us to easily filter for specific values. We can now easily export our JSON log elsewhere for several different reasons. These could include data analytics for when system failures tend to occur more frequently, data visualizations showing trends, or even dashboard-style log analyzing.
How Coralogix can use your indexed fields
Coralogix supports a wide array of tools to analyze and report on your logs. These range from simple threshold alerts to much more sophisticated, machine learning analysis to detect flow or error anomalies in your logs. This capability allows you to instantly take advantage of the values you have just configured in your logging solutions, improving the visibility of your system and minimizing your mean time to recovery.
High-Performance Logging
Let’s say we were implementing the logger into a high-performance environment. Latency from the logger must be minimal, as it could be being called thousands of times. Asynchronous logging improves application performance. It allows you to execute I/O operations in a separate thread. log4j 2 is the successor to log4j and allows you to use asynchronous loggers easily.
This screenshot, taken from the official log4j documentation, shows us exactly the power that the log4j 2 Async Loggers give us when it comes to response time in your application. If you are dealing with a huge codebase or especially high-performance algorithms, you can cut down response time from your logger by an entire order of magnitude.
Build an App using Async Logging
Let’s build a simple log4j 2 Async Logger. Create a new maven project, and name it asyncLogger. Add the following new dependencies to your POM file:
- slf4j-api – 1.7.9
- log4j-slf4j-impl – 2.13.3
- log4j-api – 2.13.3
- log4j-core – 2.13.3
- disruptor – 3.4.2
The disruptor jar file will allow us to execute low-latency queues through asynchronous means. We need this in order to get our log4j 2 implementations working as we want them to. We are now ready to create a new file, within our src directory: asyncLogger.java
NOTE: Make sure that these are added not only as build dependencies, but also as runtime dependencies.
Add the following to asyncLogger.java:
package asyncLogger;
import org.apache.logging.log4j.Logger;
import java.util.Scanner;
import org.apache.logging.log4j.LogManager;
public class asyncLogger {
public static void main(String[] args) {
Logger logger = LogManager.getLogger(asyncLogger.class);
logger.info("This is an async logger!");
logger.error("This is an error!");
}
}
We are just making one simple call to the logger – we could theoretically implement it exactly as we did for the other logger – we have just kept it simple to demonstrate the asynchronous logger.
Similar to our log4j implementation earlier, log4j 2 also uses a configuration file to define the runtime behavior of your logger.
Within the src directory, create a new file, and call it log4j2.xml. Instead of using a properties file, this time we will be using an xml file to define our logging configuration. We will use the default one provided by the official documentation:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<Console name="Console-Appender" target="SYSTEM_OUT">
<PatternLayout>
<pattern>
[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
</pattern>>
</PatternLayout>
</Console>
<File name="File-Appender" fileName="logs/asyncLog.log" >
<PatternLayout>
<pattern>
[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="asyncLogger" level="debug">
<AppenderRef ref="File-Appender"/>he preceding c
</Logger>
<Root level="debug">
<AppenderRef ref="Console-Appender"/>
</Root>
</Loggers>
</Configuration>
Run the application with some sample inputs to make sure it is working correctly. You should see the logged outputs happening in the console. A log file is also created in the root directory, within logs/asyncLog.log. As it stands, it is not yet asynchronous and is in debug mode.
2020-08-17 22:15:59,988 main DEBUG LoggerContext[name=55054057, org.apache.logging.log4j.core.LoggerContext@359df09a] started OK.
It is using the default LoggerContext. This is because we need to set a system property to make sure that the asynchronous logger implementation is being used instead of the default one.
To do so on eclipse, click: Run -> Run Configurations… -> Arguments. Paste the following into VM Arguments:
-Dlog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
Click run, or execute the program with the following inputs: Sally, Saturday. You should see output similar to this, with a lot more debug statements:
/Users/lukenolan/eclipse-workspace/asyncLogger/src/asyncLogger/log4j2.xml (org.apache.logging.log4j.core.async.AsyncLoggerContext@798162bc) with optional ClassLoader: null
2020-08-17 22:20:05,330 main DEBUG Shutdown hook enabled. Registering a new one.
[INFO ] 2020-08-17 22:20:10.341 [main] asyncLogger - This is an async logger!
[ERROR ] 2020-08-17 22:20:10.341 [main] asyncLogger - This is an error!
Your output will actually be significantly larger, as we are using the “debug” flag in the configuration XML file. This is to see if the logger is actually behaving asynchronously. As we can see, it is in fact working as intended, and we have successfully implemented the asynchronous logger for log4j 2. As we can notice the context has changed to:
2020-08-17 22:20:05,329 main DEBUG Reconfiguration complete for context[name=AsyncContext@55054057]
Conditional Logging
Detailed logs are important but sometimes can needlessly get in the way of a troubleshooting scenario. Log4j and Log4j2 both offer us configuration file filters that allow us to conditionally log information. This means that the actual source code does not need to be flooded with silly conditionals that filter whether or not a log statement gets executed. There are lots of available filters in Log4j2.
Let’s implement conditional logging within our latest log4j 2 example application. Navigate to the log4j2.xml file and change it to the following:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<Console name="Console-Appender" target="SYSTEM_OUT">
<PatternLayout>
<pattern>
[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
</pattern>>
</PatternLayout>
<ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
</Console>
<File name="File-Appender" fileName="logs/xmlfilelog.log" >
<PatternLayout>
<pattern>
[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
</pattern>
</PatternLayout>
<ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
</File>
</Appenders>
<Loggers>
<Logger name="asyncLogger" level="debug">
<AppenderRef ref="File-Appender"/>he preceding c
</Logger>
<Root level="debug">
<AppenderRef ref="Console-Appender"/>
</Root>
</Loggers>
</Configuration>
We added the ThresholdFilter, shown in the two identical lines that we added:
<ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
The logger should now only output statements labeled as errors and reject the rest of the log statements. With such a configuration, over a large codebase, you can save enormous amounts of latency and response time by filtering your logs to work for you contextually. The best part: it requires one line of code modification. Say goodbye to individually changing thousands of log statements to fit a niche use case. Run the program with the following inputs: Sally, Saturday
You should only get the following additional log output in your logfile/console:
[ERROR ] 2020-08-17 22:20:10.341 [main] asyncLogger - This is an error!
Using the Log Severity in Coralogix
Coralogix supports querying logs by a number of fields, but one of the most common use cases is to filter out logs below a certain error level. This allows users to zone in on the problems and filter out the noise in their logs. This speeds up troubleshooting and allows engineers to get to the root of the problem, far more quickly.
Conclusion
We have shed some light on the best practices when it comes to logging within a Java application environment. The main takeaways from this, alongside the implementations we have done, are:
- slf4j and how it interacts within your java application, with emphasis on its decoupled nature.
- Using log4j within the slf4j abstraction.
- Logging to the console as well as to a centralised log file – Important distinction based on your own development needs.
- Making JSON object based logs using log4j, with reference to using it with Logback.
- How to asynchronously log using log4j 2 when within a high-performance context, or looking to shave latency and response time.
- Conditional logging to ensure you are always logging exactly what you want.
Oh no!We didn’t find anything for “”,
