Logging is one of the functionalities frequently given lower priority during the development of an application; the price is usually paid later, when the application does not behave as expected and there's the need to investigate where things aren't right.
It's crucial that the components of an application log activity and unexpected situations properly. This allows us to trace the root cause of issues, in which scenarios they occur, and improves the chances of finding a fix for them.
In our case study so far, we've made poor use of logging and written a few messages to the standard error stream when things went wrong. Now that we've had a good look at the principles of integrating with an OSGi framework, it's time to take a closer look at the logging side of things.
In this chapter, we will:
- Learn a little bit about logging in general and in the context of OSGi
- Look at the Apache Felix Log Service implementation and its
logcommand - Update our bundles to use the framework logging system
Logging is an important facet of any application. When things don't go as expected, proper logs provide a great deal of information that can be used in the troubleshooting and root cause analysis activities.
Proper logging is a fine balance between giving useful contextual information and error traces and keeping it at low volume to avoid visibility clutter and performance impact. Being able to fine-tune the level of detail of the information that is received while the service platform is available (at runtime) is a valuable functionality. It allows the operational support team to drop down to a low level of details when additional information is needed, while keeping the system at the highest performance when it is running as expected.
To better classify logged activity and error situations, a log entry is typically tagged with a level of severity. The log levels defined for the OSGi Log Service are:
|
Level Name |
Level Severity |
Level Description |
|---|---|---|
|
DEBUG |
4 |
Use the 'debug' level to log relatively "verbose" information, usually targeted at the developer/tester of the component. Debug level log entries containing contextual information on the details of the execution progress, they may contain information such as entry into a method, the parameter values, algorithm steps, return of calls, and so on. |
|
INFO |
3 |
Use the 'info' level to log light notifications on component activity or changes in state. Info level log entries do not contain information that relates to error situations. |
|
WARNING |
2 |
Use the 'warning' level to notify the encounter of a situation that's currently not a problem, but may be the hint of upcoming errors. It may also be used to send a notification of an unexpected error situation that was recovered. Warning level logs must contain enough contextual information to be used by a monitoring system for attempts to determine a root cause or correlate multiple messages. |
|
ERROR |
1 |
Use the 'error' level to notify of encountered error situations that require immediate attention. Error level log entries are usually also accompanied with an exception that was thrown. They must also contain enough contextual information for use by monitoring systems. |
The log severity represents that level numerically— severity 1 is the highest. This numeric value is used to set a threshold on the level of logs to filter when showing log entries. For example, a threshold at WARNING level (=2) would show only WARNING and ERROR (=1) log entries, but not INFO and DEBUG.
Note
Some of the logging APIs also include the 'trace' and 'critical' or 'fatal' log levels. The 'trace' level is finer than 'debug' and would be used for very verbose logs. The 'critical' or 'fatal' levels would be used to notify of an unrecoverable error state, typically requiring immediate system maintenance.
Depending on the logging system that's in place, the logs that the application sends may be treated in many ways: they can be written to file, kept in memory, transmitted to an external logging component, and so on.
It is also possible (and recommended) to set up an external platform monitoring system that would react to warnings and error messages by sending an alert to an administrator or taking some corrective action. This stresses the importance of picking the right logging level when sending log messages. Typical monitoring systems only listen to warning and errors. Using an incorrect logging level may result in the monitoring system ignoring the message.
The contents of the log message are of equal importance. On large systems, with many components running (and logging) at the same time, logs from those components will most likely be interlaced. It is therefore important to include contextual information in the logged messages, as well as include a unique key (message code) that can be easily extracted by a monitoring tool.
Say, for example, that you're trying to connect to a URL and are including logging for when this connection fails:
try
{
log.debug("Connecting to: " + url);
connection = connect(url);
}
catch (IOException e)
{
log.error("Error connecting", e);
}
The error message follows the info message, so one would say the URL information was already provided— wrong. This piece of code could be called by different parties at the same time. The error message for one call may not follow its info message directly. Furthermore, if a monitoring component only logs errors, it won't have access to the URL.
Consider the following as a better alternative:
try
{
log.info("Connecting to: [{0}]", url);
connection = connect(url);
}
catch (IOException e)
{
log.error("Error connecting to [{0}]", e, url);
}
Making sure each message holds enough contextual information to know what's going on is crucial; it allows an easier analysis of error situations.
Notice also the other difference with the initial code block, which is the use of a message pattern and passing of the URL as a parameter. This has quite a few benefits such as allowing the externalization of the message patterns and potentially localizing them (including alternative language translations). It also avoids concatenation in the main code and delaying it to a later time.
Another piece of information that's usually included with log messages is the identity of the sender; this is also important. In addition to it providing information on the context of the log, it also allows filtering based on the source of the message.