Personally...In the early days it was var_dump() and alert("It works"). Then I discovered the console…(thanks to Firebug and much later, Chrome DevTool) and I dropped alert in favor of console.log() And that was it... This was what "logging" was mainly about: A process of ascertaining the correctness of the software as we develop…
But as soon as I moved into building software systems on the JVM using Java, production logging became more upfront and also, the need for me, as a software developer, to proactively build logging into my application. It was not a complex switch, but looking back now, I realized that I unintentionally, for a while, approached writing production logging as if it were the ones that took place while development.
They are in no way the same...
First, there are more moving parts, second, the purpose differs: Including the ability for an application to write out log messages in production is to have insight into the internal state of the application and also, so as to provide a good source of forensics in case something goes wrong. It has even been estimated that any trivial system would have about 4% of its code base dedicated to logging. This shows how important production logging should be.
This post thus captures the new eyes with which I had to view production logging compared to the type I had long been familiar with; which is logging during development. It is written with logback in mind, which is an implementation of SLF4J, what has grown to be the standard abstraction when it comes to logging in Java
Almost all of what is mentioned would apply to any other SLF4J implementation. The difference that may exist would mostly likely be in the area of configurations...
...with that said, let’s start.
Logging Requests versus Method Calls.
This was the fundamental shift that I had to be aware of when I started working with the SLF4J logging API: that Logging is not as much as a method call, as it is a request on the Logger object to perform a log action. (the OO nerds would point out that a method call, itself is nothing but a request made on an object, yes but for this discussion I choose to view it as separate, since the nature of logging made the requesting a little more obvious).
This is what I mean:
Let say I am making use of logging during development in the browser, the following:
console.log("Logging...")
console.warn("Warn…")
console.trace("Trace…")
are basically method calls on the console object and would do almost identical things. Print a "log" message to the console, formatted slightly depending on the method call.
With SLF4J, these calls:
logger.trace("trace...")
logger.debug("debug...")
logger.info("info...")
logger.warn("warn...")
logger.error("warning...")
could be seen as slightly different when compared to the console counterpart. They could be seen instead, as requests to the logger object, to log certain messages; a request which can either be honored or ignored...
This. The fact that logging method calls become more apparent as requests to the logger object, is at the heart of the subtlety...after this, every other moving parts fell nicely in place...
The remaining part of the post takes a cursory glance at the other moving parts involved in logging: and the other components of SLF4J architecture.
Logger Object and Log Levels
With method calls now seen as method requests, the whole idea of log levels and how it relates to loggers made easy sense.
You perform logging using a Logger object. A Logger object can be configured to only honor a logging request if the log request is of a particular type (or level). The method calls below, eg TRACE, DEBUG, INFO, WARN, ERROR are the log levels, and calling any of these methods indicates a request to perform a logging at that particular level. The Logger object upon which the method call is being made would honor the logging request depending on its own log level configuration.
The mechanism that determines if the Logger honors the request is as follows: Logging levels mentioned are hierarchical in nature, and we can represent this hierarchy with TRACE at the top and ERROR at the bottom.
Top -> TRACE
DEBUG
INFO
WARN
ERROR
Bottom -> OFF
A Logger would only honor a logging request if the log level is the same or below its configured log level. For example if Logger A is configured to DEBUG level, it would honor all the log request except TRACE. But if the Logger A is configured to INFO, then it would honor, INFO, WARN and ERROR logging request. How exactly do you configure the logger? We look at this in the configuration section. But with this dynamics out of the way, let us take a look at the Logger object performing the logging...
Loggers are hierarchical in nature.
Loggers are hierarchical in nature too! Not just levels. I explain:
As you probably know, a Logger object is usually created and named after the full qualifying name of the class it is used in. For example, a Logger created for a class Foo in the package bar, would be named bar.Foo.
package bar;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
class Foo {
Logger logger = LoggerFactory.getLogger(Foo.class)
// logger.getName() would be bar.Foo
}
The logger name would then be bar.Foo, but it does not end there, there is a hierarchical part to its creation. The bar.Foo logger is created to be a child of an implicitly created logger named bar, which is itself the child of a default ROOT logger.
What makes the hierarchical relationship of any interest is that log levels are inherited. For example, if bar.Foo does not have its logging level configured, but bar its parent, is configured to INFO, then this level would automatically apply to bar.Foo.
...with the hierarchical nature of Loggers out of the way, we can move forward and take a look at Appenders.
Appenders, and Appender Additivity
Appenders are the part that is responsible for the actual writing of the logs. We have log levels and we have the Logger objects, But the Logger objects do not do the actual writing out of the Logs, they delegate it to Appenders.
The Appender determines the destination of the logs being written, depending on which is used, the logs can be written to a File, Console, Network, etc…
Appenders also exhibit some sort of hierarchical nature. It is called logger additivity. What this means is that a Logger would write to its own Appender and also to the Appender of all its ancestors. So using our bar.Foo example. If bar.Foo has File as its Appender, bar has Console has its Appender, when bar.Foo prints a log message to a file, it would also be printed to the console. This behavior though, can be turned off in the configuration.
A pattern I see that uses the Appender additivity is to have only the Appender configured on the ROOT logger and none on the individual loggers. Due to the additivity nature, this works fine as the individual logs would print the log messages using the Appender of the ROOT logger.
..let us now take a look at Layouts and Encoders.
Layouts and Encoders
Although the Appender is what is responsible for writing the logs, the way it is written, the formatting is delegated to yet another component. This component could either be a Layout or an Encoder. The Appender determines the destination of the logs. Layout/Encoder takes care of how the logs are formatted.
Encoders are a more recent addition to logback. Added in 0.9.19 version. Layout is a much older component. Although they do the same thing, they are different. Layout can only take a log event and convert it into a String, an Encoder on the other hand, takes a log event and converts it into a byte array, which it can then format and write to an OutputStream.
So far so good, the basic components of Logback's implementation of the SLF4J abstraction should be familiar now. We have log levels, we have loggers that take log request and honor or reject them depending on their log level configuration, or that of their ancestors. If a log request is honored, the logger then delegates the writing of the log event to its appender (with the event also being written -if this behavior is not disabled- to the appender of its ancestors, since appenders are additive...the appenders then finally delegates the logs to a Layout or Encoder who formats the log messages in a desired way before they get written to whatever the log destination is.
So with this overview cleared, let take a quick look at configurations and configuration examples to see how these components could be configured.
Configuring Options
The preferred way of configuring Logback is by providing it an external configuration file. Logback would search the classpath for configuration files named logback.groovy, logback-test.xml, logback.xml: in that order. It expects to find one of these files as its configuration. If not, then it defaults to its defaults configuration.
Let us take a look at what a typical configuration file may look like and use that to expound on how the components we mentioned are configured.
<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <!-- encoders are assigned the type ch.qos.logback.classic.encoder.PatternLayoutEncoder by default --> <encoder> <pattern>
%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder> </appender> <root level="debug"> <appender-ref ref="STDOUT" /> </root> </configuration>
<configuration/> is the root element. the appender is configured with the <appender/> tag. encoder with </encoder> tag which must be within the <appender/> and the <root/> tag configures the ROOT logger.
The basic structure of the configuration file is then this, the <configuration/> element as the root element, followed by zero or more <appender/> elements, followed by zero or more <logger/>elements, followed by at most one <root/> element.
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<encoder>
<pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
</encoder>
</appender>
and if you are using an SMTPappender, an appender that sends the log message as an email, within its <appender/> tag you would have the various elements (eg. <smptpHost/>, <from/> <to/> etc) needed to configure it. For example:
<configuration>
<appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender">
<smtpHost>ADDRESS-OF-YOUR-SMTP-HOST</smtpHost>
<to>EMAIL-DESTINATION</to>
<to>ANOTHER_EMAIL_DESTINATION</to>
<from>SENDER-EMAIL</from>
<subject>TESTING: %logger{20} - %m</subject>
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%date %-5level %logger{35} - %message%n</pattern>
</layout>
</appender>
<root level="DEBUG">
<appender-ref ref="EMAIL" />
</root>
</configuration>
The value given to the class attribute should also be noted. with the FILE appender the value is ch.qos.logback.core.FileAppender which is the class that makes writing logging to filesystem possible while in the SMTP appender example, it is ch.qos.logback.classic.net.SMTPAppender.
The examples shown so far has had an appender configuration and a configuration for a ROOT logger. Since all loggers inherit from the ROOT logger, they can pick their configurations (log level, which appender to write too, etc) from the ROOT logger. But it is also possible to explicitly configure the loggers. for example:
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>app.log</file>
<encoder>
<pattern>
%date %level [%thread] %logger{10} [%file:%line] %msg%n
</pattern>
</encoder>
</appender>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<!-- encoders are assigned the type
ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
<encoder>
<pattern>
%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
</pattern>
</encoder>
</appender>
<logger name="bar.Foo" level="INFO"/>
<logger name="bar" level="TRACE">
<appender-ref=”FILE”/>
</logger>
<root level="DEBUG">
<appender-ref ref="STDOUT" />
</root>
</configuration>
In above, two loggers were configured. bar.Foo and bar. The configuration for bar.Foo only specifies the level to INFO. Since logger are hierarchical, the bar.Foo logger would pick the appender specified in the root logger, which is STDOUT. the bar logger on the other hand has both its level and appender configured and thus these would be used.
Also the configuration snippets shown so far has had an Encoder configured for the appender. this is done within the <encoder/> tag with the actual format pattern specified within the <pattern/> tags within the <encoder/> tag. The format pattern is closely related to the conversion pattern of the printf function in C.
Instead of Encoder, Layout can be used, and the configuration would look thus:
<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>
%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern> </layout> </appender> <root level="debug"> <appender-ref ref="STDOUT" /> </root> </configuration>
You can read more about the patterns here
There are a lot of configuration options available and different parts of logback that can be configured that is not shown in these few examples. You can read the configuration chapter of the Logback manual for more information.
There is definitely a lot more to know about SLF4J in general and logback in particular. Their respective official documentations are good places to get more in depth knowledge. Hopefully my experience with getting familiar with them, and the general overview shared in this post, would help anybody approaching these technologies for the first time.
No comments:
Post a Comment