Chapter 7: Filters
Have lots of ideas and throw away the bad ones. You aren't going to have good ideas unless you have lots of ideas and some sort of principle of selection.
—LINUS PAULING
In the preceding chapters, the basic selection rule, which lies at the heart of logback-classic, has been presented. In this chapter, additional filtering methods will be introduced.
Logback filters are based on ternary logic allowing them to be assembled or chained together to compose an arbitrarily complex filtering policy. They are largely inspired by Linux's iptables.
In logback-classic
Logback-classic offers two types of filters, regular filters and turbo filters.
Regular filters
Regular logback-classic filters extend the Filter
abstract class which essentially consists of a single method,
decide()
method taking an ILoggingEvent
instance as parameter.
Filters are organized as an ordered list and are based on
ternary logic. The decide(ILoggingEvent event)
method
of each filter is called in sequence. This method returns one of
the FilterReply
enumeration values, i.e. one of DENY
,
NEUTRAL
or ACCEPT
. If the value
returned by decide
() is DENY
, then the
log event is dropped immediately without consulting the remaining
filters. If the value returned is NEUTRAL
, then the
next filter in the list is consulted. If there are no further
filters to consult, then the logging event is processed normally.
If the returned value is ACCEPT
, then the logging
event is processed immediately skipping the invocation of the
remaining filters.
In logback-classic, filters can be added to
Appender
instances. By adding one or more filters to
an appender, you can filter events by arbitrary criteria, such as
the contents of the log message, the contents of the MDC, the time
of day or any other part of the logging event.
Implementing your own Filter
Creating your own filter is easy. All you have to do is extend
the Filter
abstract class and implement the
decide()
method.
The SampleFilter class shown below provides an example. Its
decide
method returns ACCEPT for logging events
containing the string "sample" in its message field. For other
events, the value NEUTRAL is returned.
package chapters.filters; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.core.filter.Filter; import ch.qos.logback.core.spi.FilterReply; public class SampleFilter extends Filter>ILoggingEvent> { @Override public FilterReply decide(ILoggingEvent event) { if (event.getMessage().contains("sample")) { return FilterReply.ACCEPT; } else { return FilterReply.NEUTRAL; } } }
The configutation files shown next attaches a
SampleFilter
to a ConsoleAppener
.
<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="chapters.filters.SampleFilter" /> <encoder> <pattern> %-4relative [%thread] %-5level %logger - %msg%n </pattern> </encoder> </appender> <root> <appender-ref ref="STDOUT" /> </root> </configuration>
With the help of Joran, logback's configuration framework,
specifiying properties or sub-componenets to filters is also
easy. After adding the corresponding setter method in the filter
class, specify the value of the property in an xml element named
after the property, nesting it within <filter>
element.
Often times, the desired filter logic consists of two orthogonal parts, a match/mismatch test and a response depending on the match/mismatch. For example, for a given test, say message equals "foobar", one filter might respond ACCEPT on match and NEUTRAL on mismatch, and another filter might respond NEUTRAL on match and DENY on mismatch.
Taking notice of this orthogonality, logback ships with the
AbstractMatcherFilter
class which provides a
useful skeleton for specifiying the appropriate response on match
and on mistmatch, with the help of two properties, named
OnMatch and OnMismatch. Most of the regular
filters included in logback are derived from
AbstractMatcherFilter
.
LevelFilter
LevelFilter
filters events based on exact level
matching. If the event's level is equal to the configured level,
the filter accepts or denies the event, depending on the
configuration of the onMatch and onMismatch properties. Here is a sample
configuration file.
<configuration> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <encoder> <pattern> %-4relative [%thread] %-5level %logger{30} - %msg%n </pattern> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="CONSOLE" /> </root> </configuration>
ThresholdFilter
The
ThresholdFilter
filters events below the
specified threshold. For events of level equal or above the
threshold, ThresholdFilter
will respond NEUTRAL when
its decide
() method is invoked. However, events with
a level below the threshold will be denied. Here is a sample
configuration file.
<configuration> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <!-- deny all events with a level below INFO, that is TRACE and DEBUG --> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>INFO</level> </filter> <encoder> <pattern> %-4relative [%thread] %-5level %logger{30} - %msg%n </pattern> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="CONSOLE" /> </root> </configuration>
EvaluatorFilter
EvaluatorFilter
is a generic filter encapsulating an
EventEvaluator
which evaluates whether a given
criteria is met. On match and respectively on mismatch, the
EvaluatorFilter
will return the value corresponding
to onMatch and respectively to onMismatch properties.
The EventEvaluator
is an abstract class and you
can implement your own event evaluation logic by sub-classing
EventEvaluator
. However, logback-classic also ships
with a concrete evaluator implementation called JaninoEventEvaluator
which takes artibtrary java language boolean expressions as the
evaluation criteria. We refer to such java language boolean
expressions as "evaulation expressions". Evaluation
expressions enable hereto unprecedented flexibility in event
filtering. JaninoEventEvaluator
requires the Janino
library. Please see the corresponding section of the setup
document.
Evaluation expressions are compiled on-the-fly during the interpretation of the configuration file. As a user, you do not need to worry about the actual plumbing. However, it is your reponsibility to ensure that the java-language expression is boolean, that it evaluates to true or false.
Given that an evaluation expression acts on the current logging event, logback automatically exports various fields of the logging event as variables accessible from the evaluation expression. The case-sensitive names these variables is listed below.
Name | Type | Description |
---|---|---|
event | LoggingEvent |
The raw logging event associated with the logging
request. All of the following variables are also available
from the event. For example, event.getMessage()
returns the same String value as the message variable
described next.
|
message | String |
The raw message of the logging request. For some logger l, when you write l.info("Hello {}", name); where name is assigned the value "Alice", then "Hello {}" is the message. |
formatedMessage | String |
The formatted message in the logging request. For some logger l, when you write l.info("Hello {}", name); where name is assigned the value "Alice", then "Hello Alice" is the formatted message. |
logger | String |
The name of the logger. |
loggerContext | LoggerContextVO |
A restricted (value object) view of the logger context to which the logging event belongs to. |
level | int |
The int value corresponding to the level. To help create easily expressions involving levels, the default value DEBUG, INFO, WARN and ERROR are also available. Thus, using level > INFO is a correct expression. |
timeStamp | long |
The timestamp corresponding to the logging event's creation. |
marker | Marker |
The Marker object associated with the logging
request. Note that marker can be null and it is your
responsibility to check for this condition in order to avoid
NullPointerException .
|
mdc | Map |
A map containing all the MDC values at the time of the creation of the logging event. A value can be accessed by using the following expression: mdc.get("myKey"). |
throwable | java.lang.Throwable | If no exception is associated with the event, then the
value of the "throwable" variable will be null. Unfortunately,
"throwable" does not survive serialization. Thus, on remote
systems, its value will always be null. For location
independent expresisons, use the throwableProxy
variable described next.
|
throwableProxy | IThrowableProxy |
A proxy for the exception associated with the logging event. If no exception is associated with the event, then the value of the "throwableProxy" variable will be null. In contrast to "throwable", when an exception is associated with an event, the value of "throwableProxy" will be non-null even on remote systems, that is even after serialization. |
Here is a concrete example.
Example 6.: Basic event evaluator usage (logback-examples/src/main/java/chapters/filters/basicEventEvaluator.xml)<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
<evaluator> <!-- defaults to type ch.qos.logback.classic.boolex.JaninoEventEvaluator -->
<expression>message.contains("billing")</expression>
</evaluator>
<OnMismatch>NEUTRAL</OnMismatch>
<OnMatch>DENY</OnMatch>
</filter>
<encoder>
<pattern>
%-4relative [%thread] %-5level %logger - %msg%n
</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
The bold part in the above configuration file adds an
EvaluatorFilter
to a ConsoleAppender
. An
evaluator of type JaninoEventEvaluator
is then
injected into the EvaluatorFilter
. In the absence of
class attribute in the
<evaluator>
element specified by the user, joran
will infer a default type, i.e. JaninoEventEvaluator
,
for the evaluator. This is one of the few occurrences where
Joran implicitly infers the type of a component.
The expression element corresponds to the evaluation
expression just discussed. The expression
message.contains("billing")
returns a boolean
value. Notice that the message variable is exported
automatically by JaninoEventEvaluator
.
Given that the OnMatch property is set to NEUTRAL and the OnMismatch property set to DENY, this evalutor filter will drop all logging events whose message contains the string "billing".
The FilterEvents
application issues ten logging requests, numbered 0 to 9. Let us
first run FilterEvents
class without any filters:
java chapters.filters.FilterEvents src/main/java/chapters/filters/basicConfiguration.xml
All requests will be displayed, as shown below:
0 [main] INFO chapters.filters.FilterEvents - logging statement 0 0 [main] INFO chapters.filters.FilterEvents - logging statement 1 0 [main] INFO chapters.filters.FilterEvents - logging statement 2 0 [main] DEBUG chapters.filters.FilterEvents - logging statement 3 0 [main] INFO chapters.filters.FilterEvents - logging statement 4 0 [main] INFO chapters.filters.FilterEvents - logging statement 5 0 [main] ERROR chapters.filters.FilterEvents - billing statement 6 0 [main] INFO chapters.filters.FilterEvents - logging statement 7 0 [main] INFO chapters.filters.FilterEvents - logging statement 8 0 [main] INFO chapters.filters.FilterEvents - logging statement 9
Suppose that we want to get rid of the "billing statement". The basicEventEvaluator.xml configuration file listed above filters messages containing the string "billing" which is precisely the desired outcome.
Running with basicEventEvaluator.xml:
java chapters.filters.FilterEvents src/main/java/chapters/filters/basicEventEvaluator.xml
we obtain:
0 [main] INFO chapters.filters.FilterEvents - logging statement 0 0 [main] INFO chapters.filters.FilterEvents - logging statement 1 0 [main] INFO chapters.filters.FilterEvents - logging statement 2 0 [main] DEBUG chapters.filters.FilterEvents - logging statement 3 0 [main] INFO chapters.filters.FilterEvents - logging statement 4 0 [main] INFO chapters.filters.FilterEvents - logging statement 5 0 [main] INFO chapters.filters.FilterEvents - logging statement 7 0 [main] INFO chapters.filters.FilterEvents - logging statement 8 0 [main] INFO chapters.filters.FilterEvents - logging statement 9
Matchers
While it is possible to do pattern matching by invoking the matches()
method in the String
class, this incurs the cost of
compiling of a brand new Pattern
object each time the
filter is invoked. To eliminate this overhead, you can predefine
one or more Matcher
objects. Once a matcher is defined, it can be repeatedly
referenced by name in the evaluator expression.
An example should clarify the point:
Example 6.: Defining matchers in an event evaluator (logback-examples/src/main/java/chapters/filters/evaluatorWithMatcher.xml)<configuration debug="true"> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator> <matcher> <Name>odd</Name> <!-- filter out odd numbered statements --> <regex>statement [13579]</regex> </matcher> <expression>odd.matches(formattedMessage)</expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter> <encoder> <pattern>%-4relative [%thread] %-5level %logger - %msg%n</pattern> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="STDOUT" /> </root> </configuration>
Running with evaluatorWithMatcher.xml:
java chapters.filters.FilterEvents src/main/java/chapters/filters/evaluatorWithMatcher.xml
we obtain:
260 [main] INFO chapters.filters.FilterEvents - logging statement 0 264 [main] INFO chapters.filters.FilterEvents - logging statement 2 264 [main] INFO chapters.filters.FilterEvents - logging statement 4 266 [main] ERROR chapters.filters.FilterEvents - billing statement 6 266 [main] INFO chapters.filters.FilterEvents - logging statement 8
In case you need to define additional matchers, you can do so by
adding further <matcher>
elements.
TurboFilters
TurboFilter
objects all extend the
TurboFilter
abstract class. Like the regular
filters, they use ternary logic to return their evaluation of
the logging event.
Overall, they work much like the previously mentioned
filters. However, there are two main differences between
Filter
and TurboFilter
objects.
TurboFilter
objects are tied to the logging
context. Hence, they are called not only when a given appender is
used, but each and every time a logging request is issued. Their
scope is wider than appender-attached filters.
More importantly, they are called before the
LoggingEvent
object creation.
TurboFilter
objects do not require the instantiation
of a logging event to filter a logging request. As such, turbo
filters are intended for high performance filtering of logging
events, even before they are created.
Implementing your own TurboFilter
To create your own TurboFilter
component, just
extend the TurboFilter
abstract class. As previously,
when implementing a customized filter object, developing a custom
TurboFilter
only asks that one implement the
decide()
method. In the next example, we create a
slightly more complex filter:
TurboFilter
(logback-examples/src/main/java/chapters/filters/SampleTurboFilter.java)
package chapters.filters; import org.slf4j.Marker; import org.slf4j.MarkerFactory; import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.turbo.TurboFilter; import ch.qos.logback.core.spi.FilterReply; public class SampleTurboFilter extends TurboFilter { String marker; Marker markerToAccept; @Override public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) { if (!isStarted()) { return FilterReply.NEUTRAL; } if ((markerToAccept.equals(marker))) { return FilterReply.ACCEPT; } else { return FilterReply.NEUTRAL; } } public String getMarker() { return marker; } public void setMarker(String markerStr) { this.marker = markerStr; } @Override public void start() { if (marker != null && marker.trim().length() > 0) { markerToAccept = MarkerFactory.getMarker(marker); super.start(); } } }
The TurboFilter
above accepts events that contain
a specific marker. If said marker is not found, then the filter
passes the responsability to the next filter in the chain.
To allow more flexibility, the marker that will be tested can
be specified in the configuration file. Hence the getter and
setter methods. We also implemented the start()
method, to check that the option has been specified during the
configuration process.
Here is a sample configuration that makes use of our newly
created TurboFilter
.
TurboFilter
configuration (logback-examples/src/main/java/chapters/filters/sampleTurboFilterConfig.xml)
<configuration> <turboFilter class="chapters.filters.SampleTurboFilter"> <Marker>sample</Marker> </turboFilter> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern> %-4relative [%thread] %-5level %logger - %msg%n </pattern> </encoder> </appender> <root> <appender-ref ref="STDOUT" /> </root> </configuration>
Logback classic ships with several TurboFilter
classes ready for use. The MDCFilter
checks the presence of a given value in the MDC whereas DynamicThresholdFilter
allows filtering based on MDC key/level threshold associations. On
the other hand, MarkerFilter
checks for the presence of a specific marker associated with the
logging request.
Here is a sample configuration, using both
MDCFilter
and MarkerFilter
.
MDCFilter
and MarkerFilter
configuration (logback-examples/src/main/java/chapters/filters/turboFilters.xml)
<configuration> <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter"> <MDCKey>username</MDCKey> <Value>sebastien</Value> <OnMatch>ACCEPT</OnMatch> </turboFilter> <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter"> <Marker>billing</Marker> <OnMatch>DENY</OnMatch> </turboFilter> <appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%date [%thread] %-5level %logger - %msg%n</pattern> </encoder> </appender> <root level="INFO"> <appender-ref ref="console" /> </root> </configuration>
You can see this configuration in action by issuing the following command:
java chapters.filters.FilterEvents src/main/java/chapters/filters/turboFilters.xml
As we've seen previously, the FilterEvents
application issues 10 logging requests, numbered 0 to 9. Except
for requests 3 and 6, all of the requests are of level
INFO, the same level as the one assigned to the root
logger. The 3rd request, is issued at the the DEBUG
level, which is below the effective level. However, since the MDC
key "username" is set to "sebastien" just before the 3rd request
and removed just afterwards, the MDCFilter
specifically accepts the request (and only that request). The 6th
request, issued at the ERROR level, is marked as
"billing". As such, it is denied by the MarkerFilter (the second
turbo filter in the configuration).
Thus, the output of FilterEvents
application
configured with turboFilters.xml file shown above is:
2006-12-04 15:17:22,859 [main] INFO chapters.filters.FilterEvents - logging statement 0 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 1 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 2 2006-12-04 15:17:22,875 [main] DEBUG chapters.filters.FilterEvents - logging statement 3 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 4 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 5 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 7 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 8 2006-12-04 15:17:22,875 [main] INFO chapters.filters.FilterEvents - logging statement 9
One can see that the 3rd request, which should not be displayed
if we only followed the overall INFO level, appears
anyway, because it matched the first TurboFilter
requirements and was accepted.
On the other hand, the 6th request, that is an ERROR
level request should have been displayed. But it satisfied the
second TurboFilter
whose OnMatch option is set to DENY.
Thus, the 6th request was not displayed.
DuplicateMessageFilter
The DuplicateMessageFilter
merits a separate
presentation. This filter detects duplicate messages, and beyond
a certain number of repetitions, drops repeated messages.
To detect repetition, this filter uses simple String equality between messages. It does not detect messages which are very similar, varying only by few characters. For example, if you write:
logger.debug("Hello "+name0); logger.debug("Hello "+name1);
Assuming name0
and name1
have
different values, the two "Hello" messages will be considered as
unrelated. Depending on user demand, future releases may check for
string similarity, eliminating repetitions of similar but not
identical messages.
Note that in case of parameterized logging, only the raw message is taken into consideration. For example, in the next two requests, the raw messages, i.e. "Hello {}.", are identical, and thus considered as repetitions.
logger.debug("Hello {}.", name0); logger.debug("Hello {}.", name1);
The number of allowed repetitions can be specified by the AllowedRepetitions property. For example, if the said property is set to 1, then the 2nd and subsequent occurrences of the same message will be dropped. Similarly, if the said property is set to 2, then the 3rd and subsequent occurrences of the same message will be dropped. By default, the AllowedRepetitions property is set to 5.
In order to detect repetitions, this filter needs to keep references to old messages in an internal cache. The size of this cache is determined by the CacheSize property. By the default, this is set to 100.
Example 6.:DuplicateMessageFilter
configuration (logback-examples/src/main/java/chapters/filters/duplicateMessage.xml)
<configuration> <turboFilter class="ch.qos.logback.classic.turbo.DuplicateMessageFilter"/> <appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%date [%thread] %-5level %logger - %msg%n</pattern> </encoder> </appender> <root level="INFO"> <appender-ref ref="console" /> </root> </configuration>
Thus, the output for FilterEvents
application
configured with duplicateMessage.xml is:
2008-12-19 15:04:26,156 [main] INFO chapters.filters.FilterEvents - logging statement 0 2008-12-19 15:04:26,156 [main] INFO chapters.filters.FilterEvents - logging statement 1 2008-12-19 15:04:26,156 [main] INFO chapters.filters.FilterEvents - logging statement 2 2008-12-19 15:04:26,156 [main] INFO chapters.filters.FilterEvents - logging statement 4 2008-12-19 15:04:26,156 [main] INFO chapters.filters.FilterEvents - logging statement 5 2008-12-19 15:04:26,171 [main] ERROR chapters.filters.FilterEvents - billing statement 6
"logging statement 0" is the first occurrence of the
message "logging statement {}". "logging statement 1" is the first
repetition, "logging statement 2" is the second
repetition. Interestingly enough, "logging statement 3" of level
DEBUG, is the third repetition, even though it is later
dropped by virtue of the basic selection
rule. This can be explained by the fact that turbo filters are
invoked before other types of filters, including the basic
selection rule. Thus, DuplicateMessageFilter
considers "logging statement 3" as a repetition, oblivious to the
fact that it will be dropped further down in the processing
chain. "logging statement 4" is the fourth repetition and "logging
statement 5" the fifth. Statements 6 and beyond are dropped
because only 5 repetitions are allowed by default.
In logback-access
Logback-access offers most of the features available with
logback-classic. Filter
objects are available and
work in the same way as their logback-classic counterparts. They
handle access' implementation of logging events:
AccessEvent
. Thus, a customized filter for logback
access follows strictly the same rules as those for
logback-classic, except for the event type received as parameter.
On the other hand, TurboFilter
objects are supported
by logback-access.
Filters
EvaluatorFilter
objects with java expressions
supplied in in evaluator
configuration elements are
supported by logback-access. However, list implicit variables
available for constructing an expression are different. Only the
AccessEvent
object can be used by inserting the
event variable in the expression. Nevertheless the access
evaluator
is just as powerfull. All the request and
response components are reachable from the event
variable.
Here is a sample configuration that will ensure that any 404 error will be logged:
Example 6.: Access Evaluator (logback-examples/src/main/java/chapters/filters/accessEventEvaluator.xml)<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="myEval"> <expression>event.getStatusCode() == 404</expression> </evaluator> <onMismatch>NEUTRAL</onMismatch> <onMatch>ACCEPT</onMatch> </filter> <encoder> <pattern> %h %l %u %t %r %s %b </pattern> </encoder> </appender> <appender-ref ref="STDOUT" /> </configuration>
We might imagine a slightly more complex use of filters to ensure logging of 404 errors, except those returned on access to CSS resources. Here is what such a configuration would look like:
Example 6.10: Access Evaluator (logback-examples/src/main/java/chapters/filters/accessEventEvaluator2.xml)<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="Eval404"> <expression>event.getStatusCode() == 404</expression> </evaluator> <onMismatch>NEUTRAL</onMismatch> <onMatch>ACCEPT</onMatch> </filter> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="EvalCSS"> <expression>event.getRequestURI().contains("css")</expression> </evaluator> <onMismatch>NEUTRAL</onMismatch> <onMatch>DENY</onMatch> </filter> <encoder> <pattern> %h %l %u %t %r %s %b </pattern> </encoder> </appender> <appender-ref ref="STDOUT" /> </configuration>