The Art of Logging: An Exploration with Apache Log4j 2 by Gary Gregory
undefined
The Art of Logging
An exploration with Apache Log4j 2
Gary Gregory
garydgregory@gmail.com
Gary Gregory
Principal Software Engineer, Rocket Software
C
Smalltalk
Java
Apache: Commons, Log4j, HttpComponents, Xalan
Books
Thank you Dealer.com for sponsoring
this meeting and the Pumpkin Race!
Why log?
“Logs are like car insurance.
Nobody wants to pay for it, but
when something goes wrong
everyone wants the best available”
– Pablo Kraan
The Road to Nowhere (0)
S
y
s
t
e
m
.
o
u
t
.
p
r
i
n
t
l
n
(
"
S
t
a
r
t
i
n
g
"
+
n
e
w
D
a
t
e
(
)
)
;
S
y
s
t
e
m
.
c
o
n
s
o
l
e
(
)
.
p
r
i
n
t
f
(
"
S
t
a
r
t
i
n
g
%
s
“
,
n
e
w
D
a
t
e
(
)
)
;
The Road to Nowhere (1)
p
u
b
l
i
c
v
o
i
d
t
e
s
t
(
)
{p
r
i
n
t
l
n
(
"
S
t
a
r
t
i
n
g
"
+
n
e
w
D
a
t
e
(
)
)
;
}
p
r
i
v
a
t
e
v
o
i
d
p
r
i
n
t
l
n
(
S
t
r
i
n
g
m
e
s
s
a
g
e
)
{S
y
s
t
e
m
.
o
u
t
.
p
r
i
n
t
l
n
(
m
e
s
s
a
g
e
)
;
}
The Road to Nowhere (2)
p
u
b
l
i
c
s
t
a
t
i
c
b
o
o
l
e
a
n
D
E
B
U
G
=
t
r
u
e
;
p
u
b
l
i
c
v
o
i
d
t
e
s
t
(
)
{p
r
i
n
t
l
n
(
"
S
t
a
r
t
i
n
g
"
+
n
e
w
D
a
t
e
(
)
)
;
}
p
r
i
v
a
t
e
v
o
i
d
p
r
i
n
t
l
n
(
S
t
r
i
n
g
m
e
s
s
a
g
e
)
{i
f
(
D
E
B
U
G
)
{S
y
s
t
e
m
.
o
u
t
.
p
r
i
n
t
l
n
(
m
e
s
s
a
g
e
)
;
}
}
The Road to Nowhere (3)
p
u
b
l
i
c
s
t
a
t
i
c
b
o
o
l
e
a
n
D
E
B
U
G
=
B
o
o
l
e
a
n
.
g
e
t
B
o
o
l
e
a
n
(
“
E
B
U
G
"
)
;
p
u
b
l
i
c
v
o
i
d
t
e
s
t
(
)
{p
r
i
n
t
l
n
(
"
S
t
a
r
t
i
n
g
"
+
n
e
w
D
a
t
e
(
)
)
;
}
p
r
i
v
a
t
e
v
o
i
d
p
r
i
n
t
l
n
(
S
t
r
i
n
g
m
e
s
s
a
g
e
)
{i
f
(
D
E
B
U
G
)
{S
y
s
t
e
m
.
o
u
t
.
p
r
i
n
t
l
n
(
m
e
s
s
a
g
e
)
;
}
}
The Road to Nowhere (4)
Destinations
Console out, err.
Files, what format(s)?
And so on…
Event levels
Source location?
Timestamp formats
Thread info?
Configuration
On and on and on…
Key Concepts: architecture
Split Logging API and implementations
Pluggable implementations
Modern logging frameworks do this
Apache Log4j 2
SLF4J + Logback
Apache Commons Logging (API only)
JUL
Log4j 1 did not, all-in-one
Log4j API architecture
Pluggable implementation: SLF4J
Key concepts
API
Configuration
Customization/Pluggability
Key concepts APIs
LogManager
Level
Logger
Marker
More:
Flow tracing with fish tagging
Context stack and context map
LogManager
Creates Loggers
LogManager.getLogger(“com.example.SomeClass”);
LogManager.getLogger(SomeClass.class);
LogManager.getLogger();
LogManager and Message Factories
Message factories
Login OK for user {} from terminal {}
Login OK for user {0} from terminal {1}
Login OK for user %s from terminal %s
ETL processed %,d records
Message Factories
org.apache.logging.log4j.LogManager.getLogger(Class|String|Object,
MessageFactory)
FormattedMessageFactory
LocalizedMessageFactory
MessageFormatMessageFactory
ParameterizedMessageFactory
ParameterizedNoReferenceMessageFactory
SimpleMessageFactory
StringFormatterMessageFactory
Levels
How important is this event?
Who needs to know about this event?
Custom levels
6 built-in Levels
Using Levels in applications
INFO
: User Alice logged in.
WARN
: User Bob entered an invalid password.
ERROR
: User Bob entered an invalid password three times, user locked out.
DEBUG
: Loading user Bob from database jdbc:...
INFO
: Emailed user Bob: three login attempts rejected, user locked out.
ERROR
: Email to Alice bounced back; subject: Your weekly summary.
Understanding Levels vs. Loggers
Message:
What it is I am telling my audience?
Levels
How important is this?
Loggers
Who’s talking now?
Hierachical Loggers
Loggers are named
Names are hierarchical: a.b.c, a,b, a, …
Hierachical loggers example
Kitchen
Kitchen.Oven
Kitchen.Oven.BottomOven
Kitchen.Oven.BottomOven.Door
Kitchen.Oven.BottomOven.Timer
Kitchen.Oven.BottomOven.Light
Kitchen.Oven.TopOven.Door
Kitchen.Oven.TopOven.Timer
Kitchen.Oven.TopOven.Light
Kitchen.Dishwasher
Kitchen.Refrigerator
Kitchen.Refrigerator.Door
Kitchen.Refrigerator.Filter
Kitchen.Refrigerator.Light
Kitchen.Refrigerator.Freezer.Door
Kitchen.Refrigerator.Freezer.Light
And so on…
Logger configuration
Hierarchical names: com.example.app.foo
Configure a logger or whole hierarchy:
<
Root
level
=
“warn"
>
<
Logger
name
=
"javax.management"
level
=
"INFO"
/>
<
Logger
name
=
“com.example.app"
level
=
"INFO"
/>
<
Logger
name
=
“com.example.app.foo"
level
=
“DEBUG"
/>
<
Logger
name
=
“com.example.app.bar"
level
=
“TRACE"
/>
Using a Logger
logger.
debug
(“User {} logged in”, user);
logger.
info
(“User {} logged in”, user);Logger granularity
One global logger
The root logger
Nah.
One per class
Use the FQCN
One per instance?
In specific cases
Use the FQCN + instance info
Watch for lots of short lived objects
Examples
Clever logger names
One per instance
Must use the logger name to uniquely identify a logger
com.example.server.socket.8080
com.example.rest.get.GetCustomer
Getting to advanced logging (0)
logger.debug("There are " +
getUserCount()
+
" users logged in now.");
You are always building the full string before calling debug()
You are always calling getUserCount()
Both of the above happens even if debug logging is disabled!
Getting to advanced logging (1)
Guard it:
if (
logger.isDebugEnabled()
) { logger.debug("There are " + getUserCount() + " users logged in now.");}
Getting to advanced logging (3)
Parameterize it:
logger.debug("There are {}users logged in now.", getUserCount());
Getting to advanced logging (4)
Use lambdas!
logger.debug("There are {} users logged in now.", () -> getUserCount()
);
Getting to advanced message formatting
(0)
From
There are
2147483647
users logged in now.
To
There are
2,147,483,647
users logged in now.
Getting to advanced message formatting
(1)
Use a formatter logger:
Logger logger = LogManager.
getFormatterLogger()
;
logger.debug("There are %,d
users logged in now.", () -> getUserCount());
Getting to advanced message formatting
(2)
You can format numbers like this as well:
logger.debug("Gain or loss: $ %(,.2f
", delta);
Gives you:
Gain or loss: $ (12,582.19)
Getting to advanced message formatting
(3)
You can get extra fancy with dates:
Calendar c = new GregorianCalendar(1918, MAY, 11);
logger.info("Richard Feynman's Birthday: %1$tb %1$te, %1$tY
", c);
Gives you:
Richard Feynman's: May 11, 1918
Noodle on that one for a minute…
How would you only log open and close door events using loggers and levels?
You can assume that door events are logged at… what? Maybe some appliances
log door events at the INFO level and others at the DEBUG level.
What if doors from a third party library log this kind of event at TRACE,
another twist!
Understanding Markers
Instead of:
logger.info("Door opened");...
logger.info("Door closed");
Do this:
logger.info(
DOOR
, "Door opened");
...
logger.info(
DOOR
, "Door closed");
Where DOOR is a constant that defines a marker:
public static final Marker DOOR =
MarkerManager.getMarker(“DOOR”)
;
Configuring Makers (inclusive)
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="5">
<Appenders>
<Console name="Console" target="SYSTEM_OUT" />
</Appenders>
<Loggers>
<Root level="WARN">
<AppenderRef ref="Console" />
</Root>
<Logger name="com.example.oven" level="DEBUG" />
<Logger name="com.example.garage" level="INFO" />
</Loggers>
<Filters>
<MarkerFilter marker="DOOR" onMatch="ACCEPT" onMismatch="DENY" />
</Filters>
</Configuration>
Hiding Marked events
If instead, we wanted to hide DOOR events, we’d say:
<MarkerFilter marker=“DOOR" onMatch="DENY" onMismatch="NEUTRAL" />
Marker usage examples
I’ve used markers for:
Different kinds of hex dumps:
Compressed buffers
Decompressed buffers
IO buffers
Different kinds of SQL statements:
Queries
Batches
Prepared statements
Flow tracing (built-in Log4j)
and more
Coding Flow Tracing
public String doIt() {logger.entry();
String testMsg = compute()
return logger.exit(testMsg);
}
Configuring Flow Tracing
<File
name
=
"log"
fileName
=
"target/test.log"
append
=
"false"
>
<PatternLayout
pattern
=
"%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>
</File>
Reading Flow Tracing
19:08:07.060 TRACE com.test.TestService 38 doIt - entry parms(0)
19:08:07.060 TRACE com.test.TestService 42 doIt - exit with (Hello, World)
Flow Tracing and Better Stack Traces
19:08:07.077 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3
at com.test.TestService.exampleException(TestService.java:29) [classes/:?]
at com.test.App.main(App.java:9) [classes/:?]
at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29]
at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?]
at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?]
at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
Flow Tracing Gotcha
Class
Method
Line
All comes from a stack snapshot
Fish Tagging
Many clients
Many threads
One logger per unique client
Fish tagging with context stack
ThreadContext.push(UUID.randomUUID().toString()); // Add the fishtag;
logger.debug("Message 1");...
logger.debug("Message 2");ThreadContext.pop();
Fish tagging with context map
ThreadContext.put("id", UUID.randomUUID().toString(); // Add the fishtag;ThreadContext.put("ipAddress", request.getRemoteAddr());ThreadContext.put("loginId", session.getAttribute("loginId"));ThreadContext.put("hostName", request.getServerName());...
logger.debug("Message 1");...
logger.debug("Message 2");...
ThreadContext.clear();
Fish tagging with pattern layout
Use
%X
by itself to include the full contents of the Map.
Use
%X{key}to include the specified key.
Use
%x
to include the full contents of the Stack.
Key Concepts: Configuration
Appenders
Layouts
Filters
Appenders – where log events go
Async
Console
Failover
File
Flume
JDBC
JMS Queue
JMS Topic
JPA
Kafka
Memory-mapped file
NoSQL: CouchDB,
MongoDB
Random-access file
Rewrite
Rolling file
Rolling random-
access file
Routing
SMTP
Socket
Syslog
ZeroMQ
Layouts: What log events look like
Some appenders need a layout
Pattern layout
%d %-5level [%t][%logger] %msg%n%throwable
2015-10-25 19:23:10,652 DEBUG [main][org.jboss.logging] Logging Provider: org.jboss.logging.Log4j2LoggerProvider
2015-10-25 19:23:10,802 INFO [main][org.hibernate.Version] HHH000412: Hibernate Core {5.0.2.Final}2015-10-25 19:23:10,802 INFO [main][org.hibernate.cfg.Environment] HHH000206: hibernate.properties not found
2015-10-25 19:23:10,802 INFO [main][org.hibernate.cfg.Environment] HHH000021: Bytecode provider name : javassist
When to use %logger
Development, show
who
does the logging
Advanced configuration, for carefully control amount of logging
Layouts
CSV
GELF
HTML
JSON
Pattern
RFC 5424 (enhanced Syslog)
Serialized
Syslog
XML
Pattern Layout
%m%n
%d %-5level [%t][%logger]%notEmpty{[%markerSimpleName]} %msg%n%throwablePatternLayout %logger tricks
PatternLayout timestamp formats
CSV columns
Time Nanos
Time Millis
Level
Thread Name
Formatted Message
Logger FQCN
Logger Name
Marker
Thrown Proxy
Source
Context Map
Context Stack
CSV example
0
,
1441617184044
,
DEBUG
,
main
,
"one=1, two=2,
three=3"
,
org
.
apache
.
logging
.
log4j
.
spi
.
AbstractLogger
,,,,
org
.
apache
.
logging
.
log4j
.
core
.
layo
ut
.
CsvLogEventLayoutTest
.
testLayout
(
CsvLogEventLayoutTest
.
java
:
98
),{},[]JSON example
[
{"logger":"com.foo.Bar",
"timestamp":"1376681196470",
"level":"INFO",
"thread":"main",
"message":"Message flushed with immediate flush=true"
},
{"logger":"com.foo.Bar",
"timestamp":"1376681196471",
"level":"ERROR",
"thread":"main",
"message":"Message flushed with immediate flush=true"
}
]
XML example
1.
<?
xml version
=
"1.0"
encoding
=
"UTF-8"
?>
2.
<Events
xmlns
=
"http://logging.apache.org/log4j/2.0/events"
>
3.
<Event
logger
=
"com.foo.Bar"
timestamp
=
"1373436580419"
level
=
"INFO"
thread
=
"main"
>
4.
<Message>
<![CDATA[This is a log message 1]]>
</Message>
5.
<Marker
parent
=
"Parent Marker"
><Child
Marker
></Marker>
6.
</Event>
7.
<Event
logger
=
"com.foo.Baz"
timestamp
=
"1373436580420"
level
=
"INFO"
thread
=
"main"
>
8.
<Message>
<![CDATA[This is a log message 2]]>
</Message>
9.
<Marker><The
Marker
Name
></Marker>
10.
</Event>
11.
</Events>
Know you audience
You’re a developer
Debug and trace your own code
DEBUG Opening file config.xml…
DEBUG Reading account
alice@example.com
from…
TRACE Enter connectJdbc(“jdbc:…”)
TRACE Exit connectJdbc(“jdbc:…”): true
You inform users:
Display status:
INFO Starting server on port 80
INFO Listening for requests…
Know you audience
No clear cut rules
A warning to a developer may not be appropriate for a user
WARN Failed to connect to database DB1, failing over to DB2.
WARN Failed logon attempt #2, one more try before account lock out.
Asynchronous logging
Asynchronous Logging
Asynchronous Loggers
Synchronous logging
Asynchronous logging
LMAX Disruptor library
Mule ESB latency vs. concurrency
“how much latency was added
as we added more concurrent
messages. The blue line are the
results of using Mule 3.5. The
green line represent the latency
of doing no logging at all. The
read line are the results using
the new logging infrastructure.
Hey wait? Where’s the red
line?! Look closely, it’s almost
on top of the green line, which
means that now logging
doesn’t add any significant
latency.
“
http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/
Mule ESB throughput vs. concurrency
“we see how many TPS
(transactions per second) were
delivered as the concurrency
increased. Again, we see our new
asynchronous logging
infrastructure performing very
closely to not logging at all and
showing a huge improvement
from our prior solution.”
http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/
What we did not talk about
Custom loggers
Custom levels
Custom appenders
Custom layouts
Custom message factories
Using multiple-inheritance with Markers
The plugin system
Logger contexts
Web app configuration
Learning more
Gary Gregory
garydgregory@gmail.com
https://garygregory.wordpress.com/
Log4j
https://logging.apache.org/log4j/2.x
https://logging.apache.org/log4j/2.x/articles.html
Q & A
Delve into the world of logging with Apache Log4j 2 through the insightful exploration presented by Gary Gregory, a Principal Software Engineer at Rocket Software. Discover the importance of logging, key concepts like logging architecture and APIs, and the significance of modern logging frameworks such as Apache Log4j 2 and SLF4J with Logback.
Download Presentation
Please find below an Image/Link to download the presentation.
The content on the website is provided AS IS for your information and personal use only. It may not be sold, licensed, or shared on other websites without obtaining consent from the author. Download presentation by click this link. If you encounter any issues during the download, it is possible that the publisher has removed the file from their server.
E N D
Presentation Transcript
The Art of Logging An exploration with Apache Log4j 2 Gary Gregory garydgregory@gmail.com
Gary Gregory Principal Software Engineer, Rocket Software C Smalltalk Java Apache: Commons, Log4j, HttpComponents, Xalan Books
Thank you Dealer.com for sponsoring this meeting and the Pumpkin Race!
Why log? Logs are like car insurance. Nobody wants to pay for it, but when something goes wrong everyone wants the best available Pablo Kraan
The Road to Nowhere (0) System.out.println("Starting " + new Date()); System.console().printf("Starting %s , new Date());
The Road to Nowhere (1) public void test() { println("Starting " + new Date()); } private void println(String message) { System.out.println(message); }
The Road to Nowhere (2) public static boolean DEBUG = true; public void test() { println("Starting " + new Date()); } private void println(String message) { if (DEBUG) { System.out.println(message); } }
The Road to Nowhere (3) public static boolean DEBUG = Boolean.getBoolean( EBUG"); public void test() { println("Starting " + new Date()); } private void println(String message) { if (DEBUG) { System.out.println(message); } }
The Road to Nowhere (4) Destinations Console out, err. Files, what format(s)? And so on Event levels Source location? Timestamp formats Thread info? Configuration On and on and on
Key Concepts: architecture Split Logging API and implementations Pluggable implementations Modern logging frameworks do this Apache Log4j 2 SLF4J + Logback Apache Commons Logging (API only) JUL Log4j 1 did not, all-in-one
Key concepts API Configuration Customization/Pluggability
Key concepts APIs LogManager Level Logger Marker More: Flow tracing with fish tagging Context stack and context map
LogManager Creates Loggers LogManager.getLogger( com.example.SomeClass ); LogManager.getLogger(SomeClass.class); LogManager.getLogger();
LogManager and Message Factories Message factories Login OK for user {} from terminal {} Login OK for user {0} from terminal {1} Login OK for user %s from terminal %s ETL processed %,d records
Message Factories org.apache.logging.log4j.LogManager.getLogger(Class|String|Object, MessageFactory) FormattedMessageFactory LocalizedMessageFactory MessageFormatMessageFactory ParameterizedMessageFactory ParameterizedNoReferenceMessageFactory SimpleMessageFactory StringFormatterMessageFactory
Levels How important is this event? Who needs to know about this event? Custom levels
Using Levels in applications INFO : User Alice logged in. WARN : User Bob entered an invalid password. ERROR: User Bob entered an invalid password three times, user locked out. DEBUG: Loading user Bob from database jdbc:... INFO : Emailed user Bob: three login attempts rejected, user locked out. ERROR: Email to Alice bounced back; subject: Your weekly summary.
Understanding Levels vs. Loggers Message: What it is I am telling my audience? Levels How important is this? Loggers Who s talking now?
Hierachical Loggers Loggers are named Names are hierarchical: a.b.c, a,b, a,
Hierachical loggers example Kitchen Kitchen.Refrigerator Kitchen.Oven Kitchen.Refrigerator.Door Kitchen.Oven.BottomOven Kitchen.Refrigerator.Filter Kitchen.Oven.BottomOven.Door Kitchen.Refrigerator.Light Kitchen.Oven.BottomOven.Timer Kitchen.Refrigerator.Freezer.Door Kitchen.Oven.BottomOven.Light Kitchen.Refrigerator.Freezer.Light Kitchen.Oven.TopOven.Door And so on Kitchen.Oven.TopOven.Timer Kitchen.Oven.TopOven.Light Kitchen.Dishwasher
Logger configuration Hierarchical names: com.example.app.foo Configure a logger or whole hierarchy: <Root level= warn"> <Logger name="javax.management" level="INFO" /> <Logger name= com.example.app" level="INFO" /> <Logger name= com.example.app.foo" level= DEBUG" /> <Logger name= com.example.app.bar" level= TRACE" />
Using a Logger logger.debug( User {} logged in , user); logger.info( User {} logged in , user);
Logger granularity One global logger The root logger Nah. One per class Use the FQCN One per instance? In specific cases Use the FQCN + instance info Watch for lots of short lived objects Examples
Clever logger names One per instance Must use the logger name to uniquely identify a logger com.example.server.socket.8080 com.example.rest.get.GetCustomer
Getting to advanced logging (0) logger.debug("There are " + getUserCount() + " users logged in now."); You are always building the full string before calling debug() You are always calling getUserCount() Both of the above happens even if debug logging is disabled!
Getting to advanced logging (1) Guard it: if (logger.isDebugEnabled()) { logger.debug("There are " + getUserCount() + " users logged in now."); }
Getting to advanced logging (3) Parameterize it: logger.debug("There are {} users logged in now.", getUserCount());
Getting to advanced logging (4) Use lambdas! logger.debug("There are {} users logged in now.", () -> getUserCount());
Getting to advanced message formatting (0) From There are 2147483647 users logged in now. To There are 2,147,483,647 users logged in now.
Getting to advanced message formatting (1) Use a formatter logger: Logger logger = LogManager.getFormatterLogger(); logger.debug("There are %,d users logged in now.", () -> getUserCount());
Getting to advanced message formatting (2) You can format numbers like this as well: logger.debug("Gain or loss: $ %(,.2f", delta); Gives you: Gain or loss: $ (12,582.19)
Getting to advanced message formatting (3) You can get extra fancy with dates: Calendar c = new GregorianCalendar(1918, MAY, 11); logger.info("Richard Feynman's Birthday: %1$tb %1$te, %1$tY", c); Gives you: Richard Feynman's: May 11, 1918
Noodle on that one for a minute How would you only log open and close door events using loggers and levels? You can assume that door events are logged at what? Maybe some appliances log door events at the INFO level and others at the DEBUG level. What if doors from a third party library log this kind of event at TRACE, another twist!
Understanding Markers Instead of: logger.info("Door opened"); ... logger.info("Door closed"); Do this: logger.info(DOOR, "Door opened"); ... logger.info(DOOR, "Door closed"); Where DOOR is a constant that defines a marker: public static final Marker DOOR = MarkerManager.getMarker( DOOR );
Configuring Makers (inclusive) <?xml version="1.0" encoding="UTF-8"?> <Configuration status="WARN" monitorInterval="5"> <Appenders> <Console name="Console" target="SYSTEM_OUT" /> </Appenders> <Loggers> <Root level="WARN"> <AppenderRef ref="Console" /> </Root> <Logger name="com.example.oven" level="DEBUG" /> <Logger name="com.example.garage" level="INFO" /> </Loggers> <Filters> <MarkerFilter marker="DOOR" onMatch="ACCEPT" onMismatch="DENY" /> </Filters> </Configuration>
Hiding Marked events If instead, we wanted to hide DOOR events, we d say: <MarkerFilter marker= DOOR" onMatch="DENY" onMismatch="NEUTRAL" />
Marker usage examples I ve used markers for: Different kinds of hex dumps: Compressed buffers Decompressed buffers IO buffers Different kinds of SQL statements: Queries Batches Prepared statements Flow tracing (built-in Log4j) and more
Coding Flow Tracing public String doIt() { logger.entry(); String testMsg = compute() return logger.exit(testMsg); }
Configuring Flow Tracing <File name="log" fileName="target/test.log" append="false"> <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/> </File>
Reading Flow Tracing 19:08:07.060 TRACE com.test.TestService 38 doIt - entry parms(0) 19:08:07.060 TRACE com.test.TestService 42 doIt - exit with (Hello, World)
Flow Tracing and Better Stack Traces 19:08:07.077 DEBUG com.test.TestService 32 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3 at com.test.TestService.exampleException(TestService.java:29) [classes/:?] at com.test.App.main(App.java:9) [classes/:?] at com.test.AppTest.testApp(AppTest.java:15) [test-classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.6.0_29] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[?:1.6.0_29] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[?:1.6.0_29] at java.lang.reflect.Method.invoke(Method.java:597) ~[?:1.6.0_29] at org.junit.internal.runners.TestMethodRunner.executeMethodBody(TestMethodRunner.java:99) [junit-4.3.1.jar:?] at org.junit.internal.runners.TestMethodRunner.runUnprotected(TestMethodRunner.java:81) [junit-4.3.1.jar:?] at org.junit.internal.runners.BeforeAndAfterRunner.runProtected(BeforeAndAfterRunner.java:34) [junit-4.3.1.jar:?] at org.junit.internal.runners.TestMethodRunner.runMethod(TestMethodRunner.java:75) [junit-4.3.1.jar:?] at org.junit.internal.runners.TestMethodRunner.run(TestMethodRunner.java:45) [junit-4.3.1.jar:?] at org.junit.internal.runners.TestClassMethodsRunner.invokeTestMethod(TestClassMethodsRunner.java:66) [junit-4.3.1.jar:?]
Flow Tracing Gotcha Class Method Line All comes from a stack snapshot
Fish Tagging Many clients Many threads One logger per unique client
Fish tagging with context stack ThreadContext.push(UUID.randomUUID().toString()); // Add the fishtag; logger.debug("Message 1"); ... logger.debug("Message 2"); ThreadContext.pop();
Fish tagging with context map ThreadContext.put("id", UUID.randomUUID().toString(); // Add the fishtag; ThreadContext.put("ipAddress", request.getRemoteAddr()); ThreadContext.put("loginId", session.getAttribute("loginId")); ThreadContext.put("hostName", request.getServerName()); ... logger.debug("Message 1"); ... logger.debug("Message 2"); ... ThreadContext.clear();
Fish tagging with pattern layout Use %X by itself to include the full contents of the Map. Use %X{key} to include the specified key. Use %x to include the full contents of the Stack.
