Friday, September 26, 2014

What are you Logging about?

Every application today needs some kind of way to report out it’s actions or current state. The main reasons that we would need there reportings are:
  1. Debugging
  2. Monitoring the Applications (components) Actions
  3. Offline and Backwards Analytics
In this case we are talking about all of these actions in a JVM based environment.


Mostly when we use the phrase “To Log” in programming it means that we want to output information from our application out a user / administrator / logs monitor.
Two things that actually define a “Log File” that is a lot of Rows of:
  1. Time Stamp - some kind representation of it.
  2. Message - some kind of information about the event that occurred.

What are we going to do?

We are going to go over some of the most famous and commonly used Logging Frameworks in Java, get to know the Pros and Cons of some of them, Show some code samples and examples (you can find the full example project on GitHub), finally get to a Conclusion which is the best one to use?.

What will we be covering:
  1. Logging Common Phrases
  2. Console logging
  3. Log4J
  4. Logback
  5. Log4J 2
  6. Log4J2 vs Logback - Performance
  7. SLF4J
  8. Conclusion
(We are not going to cover the “java.util.logging”)
Logging Common Phrases
  1. Logger -
Probably this will be the Object (I do hope it’s an interface) that you’ll be using to do all of your “Logging” through.
  1. Logging level -
The logging frameworks have almost the same names for the logging levels, in some you’ll find them as method names and in some you’ll pass them as a parameter to the “log()” method with the message to be printed, but eventually the list is pretty the same (the order is from the most weak to the strongest): Trace, Debug, Info, Warn, Error, Fatal.
  1. Root Logger -
This is a definition of the top most logger, all of the setting applied to it, most of the time, will propagate to it’s child loggers.
  1. Appender -
Appenders are mostly definitions of pipes to different kinds of output methods to the logging framework, some of the most common are: stdout, strerr, FileAppender, RollingFileAppender, SocketAppender and more, you can understand their uses by their names.
  1. Log File -
In the most stupid way, the actual file that you are writing all of your data to. It has the characteristics we’ve mentioned above in each row, “time stamp + message”, and sometime people name the log file as something associated with the Data or Timestamp (Like: “2014-09-26-06:45-Application.log”) to easily parse and search for log file later.
Console logging
The “Hardcore” or “Old School” Way! or, as i like to call it: “The Worst Way”.
This method is used mostly for small programs or at development time, you shouldn’t use it extensively because it makes your code a nightmare to maintain, and in a large scale application, when you are watching the console where you ran the application and you suddenly see the next line that someone wrote popping every second:
$$$  ### I’m Here, This is not suppose to Happen ### $$$”.
or the uninformative one:
%%%% ------ Yeah -------- %%%%
You probably want to kill the person who did it. (If say you haven’t seen something like this in the code, you are Lying!!!)
And eventually if you want to change something after, you find yourself doing search and replace over “System.out”....and changing a lot of code.
A bit about Threading, there is a difference between System.out and System.err that you would probably not notice in the documentation, the System.err ensures that the Order of the messages that you print out via multiple thread with be like a FIFO queue because all of the things you write to the Standard Err is immediately shown to the user, when the System.out does not ensure the order. (Both of them access the write()method, that inside has a Synchronized block, but it’s about the implementation of the JVM and the Operation system behind that matters).
In short, (it’s a joke, i didn’t make it short at all)
try to avoid this method.
Log4J (Versions 1.2.X)
The veteran, it is here for long, since 2001, and he is very widely used in the world.
He is very flexible and convenient because you use one interface in you code to log all of you messages, and you can control the logging level and the output methods via a configuration file.
Lets see the example of a small Java application that i wrote to see some of the usages and the advantages and problems.
Worker.java

AbstractWorker.java

Log4JWorker.java

Log4Main.java

The explanation is in the code so i’ll write some points:
  • Double checking because of String concatenation.
  • Logger is being taken via a Factory by the class name.
  • There is a log level control by the methods being printed.
  • Log4J is a Thread safe framework.

To not lengthen this post more, there are some more important configuration settings explained in the Next Post.

So, how do we watch all of these Logs?

There is an open source project called ChainSaw, that is written in Java, and lets you see the logs in a Graphical user interface.
The thing is that the last commit to this project was around 6 years ago.

As they say in their website, “Logback is intended as a successor to the popular log4j project, picking up where log4j leaves off”. (You can read their Article about the reasons to prefer logback over log4j)
I agree with some parts, and i’ll point out some nice features that i liked about “Logback” that were missing in Log4J:
  • Automatic reloading of configuration files.
  • Automatic compression of old archived log files.
  • Conditional processing of configuration files in the XML - used for the same configuration file for different environments.
  • Implementation of Logback for the Android environment.
  • logback-classic speaks SLF4J natively (We will talk about that a bit later).
  • Log4J Translator - for configurations in case of migration

A small snippet of the logback.xml configuration file:

For more elaboration please read the Logback Manual.


Viewing logs:
Just like “Chainsaw” for log4j, we have “Lilith”, one of the differences is that this project is active today too.
(They have mentioned that Mac users might have problems with installations but they have an explanation for fixing it on their website)

Configuration of the path to the logback file:




It is the contender of logback, and the newer version of “Log4j 1.2.X”  
In their website they have a Benchmark of Performance saying that they are much better (faster) then logback.

I won’t talk much about the features of Log4J 2 because it’s mostly eye to eye with logback.

For more elaboration about Usage and configuration. Here you can find the “Log4J 2” user manual, and the Wiki pages as well.

Logback vs Log4J 2

And now for the interesting part that will convince us (or maybe not) about “Who is the winner?”
I didn’t do the comparison myself, but i’ll let you read a Great Post by Tal Weiss from “Takipi” (I really recommend reading their Blog), he did a benchmark of performance between the two and a couple of more frameworks, and the conclusion was that  Log4J 2 is the winner regarding the performance.

After talking about implementations and benchmarks, eventually we get to the point (almost).
SLF4J, Simple Logging Facade for Java, is a logging implementation that allows the User (the programmer) to plug-in the desired logging system at deployment time (and development of course).

The bindings are made through the the connectors loaded to the Java Classpath.
SLF4J has a connector Jar for every major Logging framework.
The benchmark made by Takipi was implemented via SLF4J as well with all of the different implementations.

In the “logging-example” project i’ve implemented the same code as the Log4JWoker, you can view it Here, and download the project and run it yourself.

One of the coolest things you can notice is that you can avoid the Double check in case if the string concatenation.

Notice that the “{}” inside the message is a placeholder for the parameters you pass to the logging method, and is evaluated only if the proper logging level is enabled.


You’ll see if you run it that there is a clash of Multiple Bindings and the Log output is:


And you can see that the after the clash SLF4J runs with it’s default implementation of “Logback”.


In logback and other frameworks the possibility for logging via the “log()” method, and providing the “Level” as a parameter was deprecated. Lidalia supplies a decorator for SLF4J, that allows you to access exactly that.


The list of the supported implementations of connectors is:
(and you can implement one of you own if you would like)




Conclusion:
We’ve stated and compared the different logging frameworks available in Java, and my recommendation is to use SLF4J as the facade to the logging issue, and leaving the decision to which underlying framework use to your personal taste or performance constraints.
This will leave your code clean and maintainable, and you’ll be able to use a general interface of logging over any implementation you’ll choose.
I would recommend using one the “Log4J 2” or the default “Logback” implementations, it really depends on your specific needs and tastes.


Some useful SLF4J and Log4J2 connector links:


Thank you very much for reading,

If any more elaboration is needed please write a comment :)

No comments:

Post a Comment