Transcript The Art of Logging - Gary Gregory

The Art of Logging
An exploration with Apache Log4j 2
Gary Gregory
[email protected]
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
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:


Levels


What it is I am telling my audience?
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.
Key Concepts: Configuration

Appenders

Layouts

Filters
Appenders – where log events go

Async

Kafka

SMTP

Console

Memory-mapped file

Socket

Failover


Syslog

File
NoSQL: CouchDB,
MongoDB

ZeroMQ

Flume

Random-access file

JDBC

Rewrite

JMS Queue

Rolling file

JMS Topic


JPA
Rolling randomaccess file

Routing
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

Syslog

GELF

XML

HTML

JSON

Pattern

RFC 5424 (enhanced Syslog)

Serialized
Pattern Layout

%m%n

%d %-5level [%t][%logger]%notEmpty{[%markerSimpleName]} %msg%n%throwable
PatternLayout %logger tricks
Conversion Pattern
Logger Name
Result
%c{1}
org.apache.commons.Foo
Foo
%c{2}
org.apache.commons.Foo
commons.Foo
%c{1.}
org.apache.commons.Foo
o.a.c.Foo
%c{1.1.~.~}
org.apache.commons.test.Foo o.a.~.~.Foo
%c{.}
org.apache.commons.test.Foo ....Foo
PatternLayout timestamp formats
Pattern
Example
%d{DEFAULT}
2012-11-02 14:34:02,781
%d{ISO8601}
2012-11-02T14:34:02,781
%d{ISO8601_BASIC}
20121102T143402,781
%d{ABSOLUTE}
14:34:02,781
%d{DATE}
02 Nov 2012 14:34:02,781
%d{COMPACT}
20121102143402781
%d{HH:mm:ss,SSS}
14:34:02,781
%d{dd MMM yyyy HH:mm:ss,SSS}
02 Nov 2012 14:34:02,781
%d{HH:mm:ss}{GMT+0}
18:34:02
%d{UNIX}
1351866842
%d{UNIX_MILLIS}
1351866842781
CSV columns

Time Nanos

Source

Time Millis

Context Map

Level

Context Stack

Thread Name

Formatted Message

Logger FQCN

Logger Name

Marker

Thrown Proxy
CSV example
0,1441617184044,DEBUG,main,"one=1, two=2,
three=3",org.apache.logging.log4j.spi.AbstractLogger,,,,org.apache.logging.log4j.c
ore.layout.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 [email protected] 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

[email protected]

https://garygregory.wordpress.com/
Log4j

https://logging.apache.org/log4j/2.x

https://logging.apache.org/log4j/2.x/articles.html
Q&A