In this section, I’ll present a handful of Use Cases that I hope you’ll find useful. Each Use Case will present a problem, followed by the solution to that problem. Some of these you will have already seen in the Short Cut, but I wanted to consolidate the usage patterns I’ve found to be helpful here in one place.
Every now and then, you may find that you want to just log an object, and let log4j figure out how to transform the object into something useful.
Log4j has an interface called an ObjectRenderer
, which is at the center of
log4j’s Object Rendering mechanism. Object Rendering is what log4j
uses for every object that it is asked to log—if that object doesn’t
get dropped, that is—and is log4j’s formal way to control the String
representation of an object and allows for its configuration external
to your application. Let’s take a closer look.
There are basically three paths log4j’s infrastructure takes when formatting a message to be logged:
Object to be logged is already a String. Nothing further needs to be done.
Object to be logged has no ObjectRenderer
associated with it. Call
toString()
on the
object.
Object to be logged has an ObjectRenderer
associated with it. Call
doRender()
on the
object.
Most of the time, you will be passing objects of type java.lang.String
to the various log4j API
methods. But in those cases where you want to simply “throw” an object
at the log4j API, Object Rendering can be very useful. The use cases
abound for when you might want to take advantage of this powerful
feature, but here are a few:
The code doing the logging wants to log an opaque object
(such as an Exception
)
You want to “override” the String representation of an
object whose toString()
method
you don’t want to (or can’t) change
You want to delay the cost of String construction, since the
ObjectRenderer
will only be
invoked if the message is going to be logged
Two examples of how to write an ObjectRenderer
are provided with the Example
application, one of which we have already seen several times in this
Short Cut. We have also seen how to configure an Object Renderer in
the section Configuring and Using Log4j using properties-style and
XML configuration. The example we’ve seen already is for the Queue
class, where it uses an inner class
QueueRenderer
to do its
rendering.
The WorkUnit
class also has
an ObjectRenderer
written for it
called WorkUnitRenderer
, which
looks like:
package com.makotogroup.log4j; import org.apache.log4j.or.ObjectRenderer; public class WorkUnitRenderer implements ObjectRenderer { @Override public String doRender(Object o) { if (o instanceof WorkUnit) { WorkUnit workUnit = (WorkUnit)o; return "WORKUNIT: Last prime# -> " + workUnit.getLastPrimeNumberCalculated(); } return o.toString(); } }
This renderer is very simple but illustrates a usage pattern I
have found very helpful. If the WorkUnitRenderer
is accidentally configured
for the wrong class, the instanceof
check will keep bad things from happening (like a ClassCastException
). To configure the
WorkUnitRenderer
to render WorkUnit
:
Example 11. Configuring
WorkUnitRenderer
log4j.rootLogger=WARN, Console log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.layout=org.apache.log4j.SimpleLayout log4j.logger.com.makotogroup.log4j.WorkUnit=DEBUG log4j.renderer.com.makotogroup.log4j.WorkUnit= com.makotogroup.log4j.WorkUnitRenderer
And in XML:
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' debug="true"> <renderer renderedClass="com.makotogroup.log4j.WorkUnit" renderingClass="com.makotogroup.log4j.WorkUnitRenderer"/> <appender name="Console" class="org.apache.log4j.ConsoleAppender"> <layout class="org.apache.log4j.SimpleLayout"/> </appender> <logger name="com.makotogroup.log4j.WorkUnit"> <level value="DEBUG"/> </logger> <root> <level value="WARN"/> <appender-ref ref="Console"/> </root> </log4j:configuration>
System critical information is not always conveyed appropriately. The system log cannot be watched twenty four hours a day.
Send messages of critical importance via email. Use the SMTPAppender
.
SMTPAppender
This appender is used to append log messages to a single email
and send that email message to one or more recipients each time a
triggering event is received. A triggering event
is a log event that is determined (by a TriggeringEventEvaluator
) to trigger the
appender to send an email. By default the triggering event is a log
event of level ERROR
or higher. The
SMTPAppender
keeps a circular
buffer of the newest N messages (where N is configurable), so that as
the N+1th message is stored in the buffer, the oldest message is
discarded. This appender will send an email each time it receives a
triggering event.
The following parameters are configurable:
BufferSize
The number of events that will be sent when a triggering
event is received; as new messages come in, they are stored in
the circular buffer so that only the newest BufferSize
messages are kept. By
default BufferSize
is set to
512. SMTPAppender
’s default
threshold is null
, so that
all messages passed to it are kept.
EvaluatorClass
The fully qualified name of a class that implements the
TriggeringEventEvaluator
interface, so you can override the default behavior, which is to
send an email every time an event of ERROR
or higher comes in.
From
This parameter is required, and is the email address in the “from” part of the SMTP header.
LocationInfo
Set the value of this parameter to true
(it is false
by default) if you want the
source file and line number of the logger call as part of the
message.
SMTPUsername
If your SMTP server requires authentication, use this parameter to supply the username.
SMTPPassword
If your SMTP server requires authentication, use this parameter to supply the password.
SMTPHost
This parameter is required and is the name of the SMTP host that will be used to send the message
To
This parameter is required and is the email address (e.g., [email protected]) where the email message will be sent.
The SMTPAppender
uses the
JavaMail API. If you are using JDK 5 or lower, you will also need
the JavaBeans Activation Framework. All of the required JARs are
included in the Example Application for compatibility. To get this
example to run, you will need to supply values for the required
parameters in the example_1-12.properties (or example1-12.xml) configuration
file.
Example 12 shows how we might configure the
SMTPAppender
.
Example 12. Example configuration of the SMTPAppender
log4j.rootLogger=WARN, Console, Email log4j.debug log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.layout=org.apache.log4j.PatternLayout log4j.appender.Console.layout.ConversionPattern=%c {%l}:%n [%t] %-5p - %m%n log4j.appender.Email=org.apache.log4j.net.SMTPAppender log4j.appender.Email.SMTPHost=${smtp.host} log4j.appender.Email.SMTPUsername=${smtp.username} log4j.appender.Email.SMTPPassword=${smtp.password} log4j.appender.Email.To=${smtp.to} log4j.appender.Email.From=${smtp.from} log4j.appender.Email.layout=org.apache.log4j.HTMLLayout log4j.logger.com.makotogroup.log4j.Controller=DEBUG
Both appenders are attached to the root logger so that all loggers in the application have potential access to them.
We’re also doing something here we haven’t looked at before:
notice the ${smtp.host}
value of
the SMTPHost
parameter. Log4j can
substitute system variables into the configuration file. In this case,
the values of the SMTPHost
,
SMTPUsername
, and so forth, will be
substituted from system variables. As you perused the source for the
Example Application you may have noticed a file called setvars.bat (Windows) and setvars.sh (Linux). These files contain the
actual values for these parameters, and you will need to place valid
values in these files in order for this example to work. When testing
these examples, I used my ISPs SMTP server and my login information,
but obviously I couldn’t supply these values in example code for this
Short Cut.
Remember that the default triggering event for the SMTPAppender
to send an email is a log event
of ERROR
or higher. In a well
behaved application this is a (hopefully) rare event. So to cause an
ERROR
message to be generated, I
put a method logError()
on each of
the classes so that I could trigger an email. Start the application
and point your browser to http://localhost:8090 (if this
port is not free, change Controller.java to point
to a free point and re-run the application). When the JMX management
view comes up, click on the Controller MBean (see Figure 2) and you will
see a screen like the following:
Next to the logError()
method
is a text field where we can type in the text of an error message that
will be generated. This will cause the default TriggeringEventEvaluator
to send an email.
Type in the message you want and click the logError
button to log the message. If you
have configured the SMTPAppender
correctly, you will receive an email shortly. The message will be in
HTML format (you can change this by modifying the layout used in Example 12) and will contain messages, oldest first.
The text you typed will appear at the bottom of the email as an
ERROR
event.
In the email you will see lots of output. Notice from Example 12 that the Controller logger level is set to
DEBUG
. By default, the last 512
messages above the appender’s threshold level will be kept. The idea
is that you may want some context in order to make sense of the error
message. But how much context is too much? It’s up to you, but you
have several options for reducing or increasing the number of messages
that will be sent with the email. Let’s look at two of them.
One option is to set the Threshold value of the appender. Notice
in Example 12 no Threshold value was specified,
so all messages bound for the SMTPAppender
were accepted. To reduce the
number of messages that are included, add this line to the
configuration:
log4j.appender.Email.Threshold=INFO
And all messages below the INFO level will be dropped by the appender.
The other option is to change the BufferSize
parameter. To reduce the number
of messages, add this line to the configuration:
log4j.appender.Email.BufferSize=1
In this case, only the ERROR
message that triggered the default TriggeringEventEvaluator
will be included.
To increase the number of messages, add this line:
log4j.appender.Email.BufferSize=2048
And the SMTPAppender
will
keep the newest 2048 messages (subject to the value of its Threshold
parameter you set, of
course)
These options may be combined, so that you can custom tailor
them to suit your needs. I encourage you to play around with Example 12 to get a feel for how to use the SMTPAppender
.
Use multiple appenders.
This is something we’ve already seen, but we will look closely at using multiple appenders since how you do this can have a significant impact on your production environment. In this section we will look at how to configure the Example application to use three appenders:
ConsoleAppender - messages of INFO and higher
FileAppender - all messages
SMTPAppender - ERROR and higher messages
The simplest approach to take is to attach all appenders to the root logger, so that all loggers in the application have potential access to them. This is shown in Example 13 below.
Example 13. Attach appenders to the root logger
log4j.rootLogger=WARN, Console, Email, File log4j.debug log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.Threadhole=INFO log4j.appender.Console.layout=org.apache.log4j.PatternLayout log4j.appender.Console.layout.ConversionPattern= %c {%l}:%n [%t] %-5p - %m%n log4j.appender.Email=org.apache.log4j.net.SMTPAppender log4j.appender.Email.Threshold=ERROR log4j.appender.Email.SMTPHost=${smtp.host} log4j.appender.Email.SMTPUsername=${smtp.username} log4j.appender.Email.SMTPPassword=${smtp.password} log4j.appender.Email.To=${smtp.to} log4j.appender.Email.From=${smtp.from} log4j.appender.Email.layout=org.apache.log4j.HTMLLayout log4j.appender.File=org.apache.log4j.RollingFileAppender log4j.appender.File.File=output.log log4j.appender.File.layout=org.apache.log4j.SimpleLayout log4j.logger.com.makotogroup.log4j.Controller=DEBUG
All three appenders are attached to the root logger. In this
example, DEBUG
logging for all
loggers in the com.makotogroup
hierarchy has been enabled to provide lots of messages.
It might be helpful (for debugging, maybe) to use different
appenders to handle messages of different Levels. For example,
messages of WARN
and higher may go
to one file, INFO
and higher to
another file, and DEBUG
and higher
to a third file. That configuration would look something like Example 14 below.
Example 14. Example 1-14
log4j.rootLogger=WARN, WarnFile, InfoFile, DebugFile log4j.debug log4j.appender.WarnFile=org.apache.log4j.RollingFileAppender log4j.appender.WarnFile.File=WARN.log log4j.appender.WarnFile.Threshold=WARN log4j.appender.WarnFile.layout=org.apache.log4j.PatternLayout log4j.appender.WarnFile.layout.ConversionPattern= %c {%l}--> [%t] %-5p - %m%n log4j.appender.InfoFile=org.apache.log4j.RollingFileAppender log4j.appender.InfoFile.File=INFO.log log4j.appender.InfoFile.Threshold=INFO log4j.appender.InfoFile.layout=org.apache.log4j.PatternLayout log4j.appender.InfoFile.layout.ConversionPattern= %c {%l}--> [%t] %-5p - %m%n log4j.appender.DebugFile=org.apache.log4j.RollingFileAppender log4j.appender.DebugFile.File=DEBUG.log log4j.appender.DebugFile.Threshold=DEBUG log4j.appender.DebugFile.layout=org.apache.log4j.PatternLayout log4j.appender.DebugFile.layout.ConversionPattern= %c {%l}--> [%t] %-5p - %m%n log4j.logger.com.makotogroup=DEBUG
Threshold matching drops messages below a particular threshold
but allows any at the specified threshold and higher to be logged.
What if we want to configure an appender that logs only messages of a
particular level and only that level? For that we will need a
Filter—which requires us to use XML configuration—in particular a
log4j class called LevelMatchFilter
. Example 15 shows how to configure a LevelMatchFilter
to accept only log events
of TRACE
.
Example 15. Configuring a LevelMatchFilter
to accept only log events
of TRACE
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' debug="true"> <appender name="Console" class="org.apache.log4j.ConsoleAppender"> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%c {%l}--> [%t] %-5p - %m%n"/> </layout> </appender> <appender name="TraceFile" class="org.apache.log4j.RollingFileAppender"> <param name="File" value="TRACE.html"/> <param name="Append" value="false"/> <layout class="org.apache.log4j.HTMLLayout"/> <filter class="org.apache.log4j.varia.LevelMatchFilter"> <param name="LevelToMatch" value="trace"/> </filter> <filter class="org.apache.log4j.varia.DenyAllFilter"/> </appender> <logger name="com.makotogroup"> <level value="ALL"/> </logger> <root> <level value="WARN"/> <appender-ref ref="Console"/> <appender-ref ref="TraceFile"/> </root> </log4j:configuration>
Filter chains work by executing each filter in the chain,
beginning with the first one defined in the configuration, until the
end of the chain is reached or one of the filters in the chain
returns DENY
or ACCEPT
. When a filter is consulted, if
that filter returns DENY
the
event is dropped. If ACCEPT
is
returned, the event is logged. If NEUTRAL
is returned the next filter in the
chain is consulted. If the end of the filter chain is reached
without DENY
or ACCEPT
being returned, log4j behaves—for
that log event—normally (as if the filter chain was never
there).
When you run this example, you will notice that only messages of
TRACE
are in the
TRACE.log file, even though there are lots of
DEBUG
messages being output, too,
because of the way the com.makotogroup
logger is configured. This
is because LevelMatchFilter
returns
ACCEPT
only for those events whose
level matches the one specified. You may be wondering about the
DenyAllFilter
. The TraceFile
appender has no threshold set,
which is what we want because if we set it above TRACE
, then none of the TRACE
messages will ever make it to
TRACE.log, no matter how interesting our filter
setup is. But this also has a consequence: all messages of TRACE
and higher are accepted. So, to ensure
that TRACE.log contains ONLY TRACE
messages, we include a filter
(LevelMatchFilter
) to accept
TRACE
messages and another
(DenyAllFilter
) to deny everything
else. Each instance of the LevelMatchFilter
is neutral towards any
events that do not match its LevelToMatch
property.
If we want to, say, accept only TRACE
and WARN
messages, we could do that too with the
following:
<appender name="TraceAndWarnFile" class="org.apache.log4j.RollingFileAppender"> <param name="File" value="TRACE_and_WARN.html"/> <param name="Append" value="false"/> <layout class="org.apache.log4j.HTMLLayout"/> <filter class="org.apache.log4j.varia.LevelMatchFilter"> <param name="LevelToMatch" value="warn"/> </filter> <filter class="org.apache.log4j.varia.LevelMatchFilter"> <param name="LevelToMatch" value="trace"/> </filter> <filter class="org.apache.log4j.varia.DenyAllFilter"/> </appender>
Since LevelMatchFilter
requires an exact match on Level, only WARN
and TRACE
messages are accepted, and all others
are dropped (i.e., denied) by this appender.
Log messages need to be correlated in a meaningful way from a business standpoint. This is based on information in the message itself.
Use Mapped Diagnostic Contexts (MDC).
In real-world, multi-user applications it is rare that a unit of work will follow a single, straight-line path through the application. The path a unit of work takes will twist and turn and change depending on many factors. Plus, the application—if it scales—is more than likely servicing more than one user at a time. As a unit of work traverses its way through your application, its log output leaves a trail behind it, but if you need to research a problem by looking in the log files it may be challenging at best and impossible at worst to correlate messages from different parts of your application for a single unit of work.
That is where log4j’s Diagnostic Context comes in handy, in particular the Mapped Diagnostic Context (MDC). An MDC is a key/value entity maintained by log4j on thread local storage (TLS) that can be used to make information available to different parts of the application, allowing all loggers to emit consistent log messages. As a result, a log message can be correlated to others by the content of the messages.
The Example Application attempts to simulate this by associating
a “user” from a pool of users for each WorkUnit
that is processed. Log messages can
be correlated by looking at the UserId
and UserName
properties of the WorkUnit
that is being processed, and you
can actually follow a unit of work from the time it is processed by
the Supplier
until it is completed
by the Consumer
. This requires very
little code to accomplish.
Each WorkUnit
simulates a
request (the unit of work in this case) on behalf of a user, with
which the WorkUnit
is associated.
When the WorkUnit
is created it
sets the UserId
and UserName
of the associated user in the
MDC:
public class WorkUnit { . . . public WorkUnit() { requestingUser = User.getRandomUser(); } . . . public void activate() { MDC.put(RequestRenderer.USER_ID, getRequestingUser().getUserId()); MDC.put(RequestRenderer.USER_NAME, getRequestingUser().getUserName()); requestStartTime = System.currentTimeMillis(); } . . . public void deactivate() { MDC.remove(RequestRenderer.USER_ID); MDC.remove(RequestRenderer.USER_NAME); } }
The static method User.getRandomUser()
simulates associating the WorkUnit
with a “user” as if the work that is done is on behalf of that user.
Each component that deals with a unit of work calls activate()
on that unit of work (setting the
MDC appropriately) and when finished calls deactivate()
(removing the information from
the MDC). For example, when the Supplier
creates the WorkUnit
:
public class Supplier extends Worker { . . . public void run() { getlogger().trace("Entering method run()..."); while (!isStopCalled()) { while (isSuspended()) { if (nap()) { getlogger().warn("Got interrupted!"); } } nap(); WorkUnit unitOfWork = new WorkUnit(); unitOfWork.activate(); unitOfWork.log();// Object, log thyself! . . . } . . . }
When Consumer
deals with the
WorkUnit
:
public class Consumer extends Worker { . . . public void run() { getlogger().trace("Entering method run()..."); while (!isStopCalled()) { while (isSuspended()) { try { Thread.sleep(1000); } catch (InterruptedException e) { } } WorkUnit unitOfWork = null; while (unitOfWork == null) { unitOfWork = getQueue().take(); unitOfWork.activate(); } incrementTotalProcessingTime(doWork(unitOfWork)); incrementNumberOfUnitsProcessed(1); unitOfWork.log();// Object, log thyself! unitOfWork.deactivate(); } getlogger().trace("Exiting method run()"); } } }
Notice that when Consumer
gets the unit of work from the Queue
it calls activate()
to set the context information in
the MDC. When it is finished, it calls deactivate()
. In a single threaded
application, one call to activate()
would be sufficient, but since MDC is stored as TLS, each component
must be coded to participate in this pattern so that a unit of work
can be traced through its path, even in a multi-threaded application
like the Example application.
Finally, you will need to configure the PatternLayout
to output the appropriate
mapped context:
Example 16. Example 1-16
log4j.rootLogger=WARN, Console log4j.debug log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.layout=org.apache.log4j.PatternLayout log4j.appender.Console.layout.ConversionPattern= %c [%t] %-5p |RQID=%X{request.id} USERID=%X{user.id} USERNAME=%X{user.name}| => %m%n log4j.logger.com.makotogroup=ALL log4j.renderer.com.makotogroup.log4j.WorkUnit=com.makotogroup.log4j.WorkUnit$Reques tRenderer
For each WorkUnit
that comes
through the application, the MDC will contain its requestId
, userId
, and userName
properties, and those are output
using the special %X{property_name}
notation.
This is all done by contract and convention. This is not automatic, so you will have to write some code and make sure that all parts of the application follow this convention. That is, context properties have to be named consistently, and their values have to have consistent meaning. This is potentially more of a problem where applications are maintained by multiple developers. However, as you can see, it’s very simple code to write.
Now, if you run Example 16, you will see a
dizzying array of output on the console. However, the output from each
unit of work has diagnostic context associated with it—in this case
userId
and userName
—so that it is possible to correlate
a single unit of work as it traverses through the application. With a
slight modification we can direct the output to a log file, and on
Linux at least (or on Windows if you run Cygwin) we can grep for a
single unit of work from, say, Billy:
~/workspace/log4j-example$ grep 'USERNAME=Billy' output.log
And the result will be only those lines that contain the String
“USERNAME=Billy”. Is there a way to get log4j to do this? After all,
not everyone has an awesome set of command line power tools available
to them (like we Linux users do). Fortunately there is a way, and it
involves the use of a Filter, specifically a StringMatchFilter
subclass. StringMatchFilter
looks at the rendered
message itself, which means it has been processed by the layout and
any ObjectRenderer
defined for the
message class. But this isn’t quite good enough for that we need. We
need a StringMatchFilter
that also
can look at the MDC for a specific property value. However, log4j does
not provide such a Filter, so I wrote one. Check out Example 17.
Example 17. StringMatchFilter
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' debug="true"> <renderer renderedClass="com.makotogroup.log4j.WorkUnit" renderingClass="com.makotogroup.log4j.WorkUnit$RequestRenderer"/> <appender name="Console" class="org.apache.log4j.ConsoleAppender"> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%c [%t] %-5p |%X{request.id} %X{user.id} %X{user.name}| => %m%n"/> </layout> </appender> <appender name="File" class="org.apache.log4j.FileAppender"> <param name="File" value="output.log"/> <param name="Append" value="false"/> <!-- Recreate file between runs --> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%c [%t] %-5p |%X{request.id} %X{user.id} %X{user.name}| => %m%n"/> </layout> <filter class="com.makotogroup.log4j.WithContextStringMatchFilter"> <param name="ContextPropertyToMatch" value="user.name"/> <param name="ContextPropertyValueToMatch" value="Billy"/> </filter> <filter class="org.apache.log4j.varia.DenyAllFilter"/> </appender> <logger name="com.makotogroup"> <level value="ALL"/> </logger> <root> <level value="WARN"/> <appender-ref ref="Console"/> <appender-ref ref="File"/> </root> </log4j:configuration>
If you run Example 17 and look in
output.log, you will see all messages where Billy
is the userName
in the MDC. The
StringMatchFilter
that comes
packaged with log4j only checks the rendered message for the string to
match. Because non-matches are considered neutral, once again the
DenyAllFilter
is in use
here.
Persist certain messages so they may be correlated based on their properties.
SQL is a great language for joining sets of data together, so it
seems logical that for certain types of messages we would want to
store them to a relational database in order to correlate messages
based on one or more properties of the messages themselves. For that
we need an adapter that can save the messages to the database. Log4j
comes packaged with an appender called JDBCAppender
. I prefer not to use JDBC
directly from my Java code because I like dealing with objects, so I
use Hibernate. Because of that, I wrote an adapter—HibernateAdapter
—for this Short Cut. Example 18 shows how to configure it.
Example 18. Configuring HibernateAdapter
log4j.rootLogger=WARN, Console log4j.debug log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.layout=org.apache.log4j.PatternLayout log4j.appender.Console.layout.ConversionPattern= %c [%t] %-5p |RQID=%X{request.id} USERID=%X{user.id} USERNAME=%X{user.name}| => %m%n log4j.appender.Hibernate=com.makotogroup.log4j.db.HibernateAppender log4j.logger.com.makotogroup=DEBUG,Hibernate log4j.renderer.com.makotogroup.log4j.WorkUnit=com.makotogroup.log4j.WorkUnit$Reques tRenderer
Example 18 expects there to be a MySQL database installed on the machine on which you’re running it. The Example application comes with a script to create the necessary tables to make this work. Instructions for setting up the database are located in the Example application code distribution.
HibernateAdapter
needs no
layout and has no properties to set. In Example 18 it is associated with the com.makotogroup
logger only, and if you run
this example you will see messages show up in the database. Depending
on the speed of your machine, it may also run slowly. HibernateAdapter
uses Hibernate’s default
SessionFactory
, and if you look at
hibernate.cfg.xml you’ll notice
there is not much in the way of optimizations. That I leave to
you.
Now consider Example 17. While using a
StringMatchFilter
to pull Billy’s
messages out into their own log file, we can use HibernateAdapter
to save ALL of the messages
to the DB and use SQL to pull them:
It (hopefully) goes without saying that you probably NEVER want
to persist DEBUG
or TRACE
level messages into a database for
performance reasons if for no other. However, using a technique like
this can be very handy in cases where you need to correlate messages
across various thread, VM, or physical machine boundaries based on
contextual information.
When output from multiple loggers gets interleaved it can be difficult to make sense out of it.
Use a separate appender for the verbose part(s) of the application, and turn off appender additivity for the appropriate logger(s).
We saw in section titled Appender inheritance that
through the use of configuration and turning off appender additivity
we can segregate log output. I do this all the time with Hibernate,
which I use as my O/R mapping library as I mentioned in the previous
section. Every now and then I want to see what Hibernate is doing
under the hood (when I can’t get a mapping to work correctly, for
example), and so I want to see Hibernate DEBUG
output. But I want to see my
application’s output too, and when it gets interleaved with the output
from Hibernate, well, I just can’t read it. All that great DEBUG
output from Hibernate doesn’t really
help me all that much because there’s just too much other information
getting in the way.
Consider Example 19 below, where we turn off appender additivity, and segregate different parts of the application using different appenders:
Example 19. Segregating different parts of the application using different appenders
log4j.rootLogger=WARN, Console log4j.appender.Console=org.apache.log4j.ConsoleAppender log4j.appender.Console.layout=org.apache.log4j.SimpleLayout log4j.appender.HibernateAppender=org.apache.log4j.FileAppender log4j.appender.HibernateAppender.File=hibernate.log log4j.appender.HibernateAppender.layout=org.apache.log4j.PatternLayout log4j.appender.HibernateAppender.layout.ConversionPattern= %c {%l}:%n [%t] %-5p - %m%n log4j.additivity.org.hibernate=false log4j.logger.org.hibernate=DEBUG,HibernateAppender
In this example the output from all of the loggers in the
org.hibernate
hierarchy goes to the
file hibernate.log, and - because we turned off
appender additivity for the org.hibernate
logger—nowhere else!
The neat thing about segregating appender output is that it works for any logger. The combinations are endless!
Some messages are more important from an operational standpoint than the Level they are assigned would suggest.
Use the SMTPAppender
, along
with a filter chain and a custom TriggeringEventEvaluator
to capture these
important messages.
When the Example application is about to complete its startup sequence it attempts to log a message that begins with the string “APPLICATION STARTING AT ==> …” and whose Level is INFO. In a real-world application, such a message, while informational in nature, could have serious operational meaning. For example, if your job is to ensure the application is always up and running, such a message at, say, 1:30pm would make you wonder, “Why did the application just start up at 1:30 in the afternoon?” But if you aren’t looking at the log file when this message appears, you probably won’t know the application just restarted (and thus won’t investigate why this seemingly strange thing has happened).
In Example 12 we looked at how to use the
SMTPAppender
, which by default uses
a TriggeringEventEvaluator
that
sends an email whenever an event of Level ERROR
or higher is received. However, in the
scenario above we would not see the message since it is at level
INFO
and would not trigger the
default TriggeringEventEvaluator
.
What we want is to set up an appender that has a null
Threshold, a filter chain that only
allows events whose message contains certain key String fragments, and
a TriggeringEventEvaluator
that
accepts all events.
First, we create a custom TriggeringEventEvaluator
that tells the
caller that any event triggers:
package com.makotogroup.log4j; import org.apache.log4j.spi.LoggingEvent; import org.apache.log4j.spi.TriggeringEventEvaluator; public class AcceptAllTriggeringEventEvaluator implements TriggeringEventEvaluator { @Override public boolean isTriggeringEvent(LoggingEvent event) { // This TEV accepts all events return true; } }
Next, we configure the filter chain, as shown below in Example 20.
Example 20. Configuring the filter chain
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/' debug="true"> <appender name="Console" class="org.apache.log4j.ConsoleAppender"> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%c [%t] %-5p |%X{request.id} %X{user.id} %X{user.name}| => %m%n"/> </layout> </appender> <appender name="ImportantEventSmtpAppender" class="org.apache.log4j.net.SMTPAppender"> <param name="EvaluatorClass" value="com.makotogroup.log4j.AcceptAllTriggeringEventEvaluator"/> <param name="SMTPHost" value="${smtp.host}"/> <param name="SMTPUsername" value="${smtp.username}"/> <param name="SMTPPassword" value="${smtp.password}"/> <param name="To" value="${smtp.to}"/> <param name="From" value="${smtp.from}"/> <layout class="org.apache.log4j.HTMLLayout"/> <filter class="org.apache.log4j.varia.StringMatchFilter"> <param name="StringToMatch" value="APPLICATION STARTING AT"/> </filter> <filter class="org.apache.log4j.varia.DenyAllFilter"/> </appender> <logger name="com.makotogroup"> <level value="ALL"/> <appender-ref ref="ImportantEventSmtpAppender"/> </logger> <root> <level value="WARN"/> <appender-ref ref="Console"/> </root> </log4j:configuration>
If you run Example 20 (don’t forget to
correctly configure your SMTP settings) you should receive an email
when the application has finished its startup sequence. The filter
chain for the ImportantEventSmtpAppender
is configured
with a null threshold (by omitting the Threshold parameter) so that
all events are passed through to the filter chain which denies all
events except those that contain the string “APPLICATION STARTING AT”
upon acceptance of which the AcceptAllTriggeringEventEvaluator
triggers
and an email is sent.
13.59.209.131