|
|
Logging
Logging is essential for any serious application. You will use logs to troubleshoot once your application is in production. You can write your own logging, but why (other then being fun to write)? Log4j is great, proven fast and easy. It is also open source, so if you do have a great idea, just change the code and contribute back. Logging Levels You should have several levels of logging. Usual logging levels are: - DEBUG - use only when debuging specific problem. Do not run in production with this level. It will slow you down. What should you log with this level? Almost everything, but be carefull how you log. I will write about this in a minute.
- INFO - If you are hosting a solution, you can consider running logs at this level. Entries created at this level should always give you enough information to realize where the issue is and start fixing it.
- WARN - This is a warning level. When something unexpected happens, but you can still recover and continue, use this level. For example, you are downloading and processing files from a remote site and at some point, there are no files to process. Log a warning message to indicate that there was no files available for processing. This is likely to be loging level of choice in a production environment.
- ERROR - Every error condition should be logged with this level. This does not mean that every time there is an exception, you should log an error. In many cases exceptions are propagated through the layers of your software, so the highest layer, or the layer that is actually handling the exception should do the logging. Why? To avoid duplicate log entries. Some will say that it's better to log more then less and I would agree with this in general, but if you are writing all layers, it is really not necessary or desirable to log at every level.
All this seems obvious, but to my surprise, very often it needs to be enforced. I've seen to many applications that either do not have logging, or have logging and still use System.out.println in many cases, or just log at one level. | Reserved for ads |
What to Log? Log4j offers patterns that can help you log a lot of information. There are some basic things that (in my opinion) should always be logged. Those things are: - Timestamp in the human readable format
You need a timestamp to corelate the event with the logging statement. - Logging level
- Name or id of the thread
This is extremelly important and freequently overlooked. In multi-threading environment logs become useless unless logging statements can be correlated back to the threads. - Name of the component that is issuing log statement i.e. class name
Some projects preferre module name i.e. "ordering" which is an umbrella for multiple classes and multiple packages even. I think this is a bad idea. Putting a class name here will let you troubleshoot fast and easy. - Name of the method that is issuing log statement
This is very usefull in troubleshooting and log4j can add it for you, however, there is a price to pay on performance. That is why I would suggest to create a simple wrapper and pass the name of the method as one of the arguments to your logging statement. - Message
Actual log message, description of the event.
As the final thing, here is the pattern that will let you log parts described above: %d %-5p [%t][%c{1}] %m%n %d - logs the timestamp %-5p - logs the priority %t - thread name %c{1} - last portion of the name (i.e. if you get the logger with MyClass.class.getName() if you put only %c you will end up with something like: com.mydomain.mypackage.MyClass If you put %c{1} then it's just MyClass which makes log easier to read and analyze. %m - your message that should include method name %n - new line.
Special Logger As the final entry in this writeup I wanted to mention special logging needs. Log4j comes with a number of appenders among which the most popular is probably RollingFileAppender. This appender rolls over when the log reaches certain size. You can setup the size and the number of loggs that you want to keep. When the number of logs is reached, the oldest log will be deleted. This is very usefull, but I find that sometimes I need my logs to rottate daily as well as when the predefined size of the logs is exceeded. May sound an overkill, but if you need to automate log processing, this is very usefull. There is additional dimension to this. If you are automating log processing you will probably need to minimize the footprint on the system, while maximizing the amount of data in the logs. Logs are created as simple text, so they should compress nicelly. Compressing logs can be accomplished with a cron (in Unix/Linux environment - not so natural on Windows), but if you do this, it becomes a "disconnected" operation, may kick in at any time, so you may have logs sitting uncompressed for a long time, which is what we wanted to avoid in the first place. So, I created my own DailyRollingGZIPFileAppender. What it does, it rolles daily and earlier if the predefined size is exceeded, but in addition to that, once it rolls, it will compress rolled over log in a separate thread to minimize (i.e. nutralize) impact on logging performance. Fully functional version can be found here. It is distributed under Apache Public License, so you are welcome to use it. |
|
|