Logging Best Practices

namibiancurrishInternet and Web Development

Nov 12, 2013 (3 years and 9 months ago)

219 views

Logging Best Practices

Dubna

2012

Benedicto Fernandez

Software Engineer

CERN / GS
-
AIS

Only useful for
debugging/development?

Contents


Logging libraries


Logging levels


Where to log?


Performance


How to access?


What to log?

What are we talking about?

Tracing

Logging

Auditing

First Logging:

System.out.println


Easy


Quick


No dependencies


Redirect to file or null in Production


Log everything or nothing


System.out.println(
“Start method1”
);

Example

Start method1

Before retrieve information from DB

After retrieve information from DB

Updating information

Before save information in the DB

After save information in the DB

Finish method1

Start method2

Before retrieve information from DB

Error retrieving information from DB:
NullPointerException


Next evolution:

Logging Libraries


Log4j, Java Logging…

log.info(
“Start method1”
);


Provide


Time of the message


The class, the method, the line





Print easily the stacktrace


Log to files, databases, system log
mechanisms

Example

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving
information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)

Example

06:05:56 07.11.2011

INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving
information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)

Example

06:05:56 07.11.2011 INFO (
Class1.java:211
) Start method2

06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving
information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)

Example

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 INFO (Class1.java:243) Error retrieving
information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)

Logging levels (I)


Log4j


Trace


Debug


Info


Warning


Error


Fatal


Java Logging


Finest


Finer


Fine


Config


Info


Warning


Severe

Example

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:211) Parameter
‘age’ is not an Integer

06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 DEBUG (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 ERROR (Class1.java:243) Error retrieving
information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)


Example

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an
Integer

06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 DEBUG (Class1.java:220) Before
retrieve information from DB

06:05:56 07.11.2011 ERROR (Class1.java:243) Error retrieving
information from DB: NullPointerException

java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)


Example

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an
Integer

06:05:56 07.11.2011 INFO (Class1.java:211) Finish method2

06:05:56 07.11.2011 INFO (Class1.java:211) Start method2

06:05:56 07.11.2011 DEBUG (Class1.java:220) Before retrieve
information from DB

06:05:56 07.11.2011 ERROR (Class1.java:243) Error
retrieving information from DB: NullPointerException


java.lang.NullPointerException


at pkg.Class1.method2(Class1.java:225)


at pkg.Class1.methodN(Class1.java:458)


at pkg2.ClassZ.methodUpdate(ClassZ.java:458)


at …


at java.lang.Thread.run(Thread.java:595)

Logging levels (II)

log4j.logger.ch.cern.ais=
DEBUG


log4j.logger.ch.cern.ais.package.Class1=
TRACE


log4j.logger.org.springframework=
ERROR


log4j.logger.org.springframework.ws=
INFO

Where to log?


Text files (Plain text, XML,…)


Binary files


Database


Syslog (Windows & Unix/Linux)


Network (TCP & UDP)


Where to log?


Text files (Plain text, XML,…)


Binary files


Database


Syslog (Windows & Unix/Linux)


Network (TCP & UDP)


Always to a Text file

(+ something else)?

Performance


"hidden" cost of parameter construction


logger.debug(
"Entry number: "

+ i +
" is "

+
String.valueOf(entry[i]));



Performance


"hidden" cost of parameter construction


logger.debug(
"Entry number: "

+ i +
" is "






+ String.valueOf(entry[i]));



Solution

if
(logger.isDebugEnabled()) {


logger.debug(
"Entry number: "

+ i +
" is "






+ String.valueOf(entry[i]));

}


Next evolution:

Logging Libraries v2.0


Simple Logging Facade (SLF4J)


Logback



Parameterized messages

logger.debug(
"Entry number: {} is {}“
, i


, String.valueOf(entry[i]));

Multiple users (I)


Different users working simultaneously


Log messages mixed for different users


Difficult to trace user’s actions


Multiple users (I)


Different users working simultaneously


Log messages mixed for different users


Difficult to trace user’s actions

Log User ID

Multiple users
-

Example

06:05:55 07.11.2011 INFO (Class1.java:41)
User=bfernan;
message=‘Start method1’;

06:05:55 07.11.2011 DEBUG (Class1.java:44) message=‘Before retrieve information
from DB’;

06:05:55 07.11.2011 DEBUG (Class1.java:46) message=‘After retrieve information
from DB’;

06:05:55 07.11.2011 INFO (Class1.java:50) message=‘Updating information’;

06:05:55 07.11.2011 DEBUG (Class1.java:94) message=‘Before save information in
the DB’;

06:05:56 07.11.2011 DEBUG (Class1.java:96) message=‘After save information in
the DB’;

06:05:56 07.11.2011 INFO (Class1.java:100)
User=bfernan;

message=‘Finish method1’;

06:05:56 07.11.2011 INFO (Class1.java:211)
User=xxxxxxx;

message=‘Start method2’;

06:05:56 07.11.2011 DEBUG (Class1.java:220) message=‘Before retrieve information
from DB’;

06:05:56 07.11.2011 ERROR (Class1.java:243) message=‘Error retrieving
information from DB: NullPointerException’;


Multiple users (II)


Mapped Diagnostic Contexts (MDC)

public void

serviceMethod1(String userName,…) {


String userName = getLoggedUserName();


MDC.put(
“userName”
, userName);

}




Configuration

…PatternLayout=%T User=
%X{userName}
;message=‘%m’;%n




Multiple users (III)

public void

doFilter(ServletRequest request, ServletResponse response,





FilterChain chain)
throws

IOException, ServletException {






HttpServletRequest req = (HttpServletRequest) request;








Principal principal = req.getUserPrincipal();





// Please note that we could have also used a cookie to





// retrieve the user name






if

(principal !=
null
) {







String username = principal.getName();







MDC.put(USER_KEY, username);





}






try

{







chain.doFilter(request, response);





}
finally

{







MDC.remove(USER_KEY);





}



}




Multiple users (III)

public void doFilter(ServletRequest request, ServletResponse response,





FilterChain chain) throws IOException, ServletException {






HttpServletRequest req = (HttpServletRequest) request;








Principal principal = req.getUserPrincipal();





// Please note that we could have also used a cookie to





// retrieve the user name






if (principal != null) {







String username = principal.getName();







MDC.put(USER_KEY, username);





}






try {







chain.doFilter(request, response);





} finally {







MDC.remove(USER_KEY);





}



}




Multiple users
-

Example

06:05:55 07.11.2011 INFO (Class1.java:41) User=bfernan;
message=‘Start method1’;

06:05:55 07.11.2011 DEBUG (Class1.java:44)
User=bfernan;
message=‘
Before retrieve information from DB

;

06:05:55 07.11.2011 DEBUG (Class1.java:46)
User=bfernan;
message=‘
After retrieve information from DB

;

06:05:55 07.11.2011 INFO (Class1.java:50)
User=bfernan;
message=‘
Updating information

;

06:05:55 07.11.2011 DEBUG (Class1.java:94)
User=bfernan;
message=‘
Before save information in the DB

;

06:05:56 07.11.2011 DEBUG (Class1.java:96)
User=bfernan;
message=‘
After retrieve information in the DB

;

06:05:56 07.11.2011 INFO (Class1.java:100) User=bfernan;
message=‘Finish method1’;

06:05:56 07.11.2011 INFO (Class1.java:211) User=xxxxxxx;
message=‘Start method2’;

06:05:56 07.11.2011 DEBUG (Class1.java:220)
User=xxxxxxx;
message=‘
Before retrieve information from DB

;

06:05:56 07.11.2011 ERROR (Class1.java:243)
User=xxxxxxx;
message=‘
Error retrieving information from DB: NullPointerException

;

Multiple Connections Same User (I)



Account


shared by 2+ end users


Different


Session ID


Remote Address

user1

Multiple Connections Same User (I)


“Account” shared by 2+ end users


Different


Session ID


Remote Address


Log Session ID

Log Remote IP

user1

Multiple Connections Same User (I)
-

Example

06:05:55 07.11.2011 INFO (Class1.java:41)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘Start method1’;

06:05:55 07.11.2011 DEBUG (Class1.java:44)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘
Before retrieve information from DB

;

06:05:55 07.11.2011 INFO (Class1.java:211)
IP=61.82.23.9;Session=00000002;

User=bfernan;message=‘Start method2’;

06:05:55 07.11.2011 DEBUG (Class1.java:220)
IP=61.82.23.9;Session=00000002;

User=bfernan;message=‘Before retrieve information from DB’;

06:05:55 07.11.2011 DEBUG (Class1.java:46)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘
After retrieve information from DB

;

06:05:55 07.11.2011 INFO (Class1.java:50)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘
Updating information

;

06:05:56 07.11.2011 DEBUG (Class1.java:94)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘
Before save information in the DB

;

06:05:56 07.11.2011 DEBUG (Class1.java:96)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘
After retrieve information in the DB

;

06:05:56 07.11.2011 ERROR (Class1.java:243)
IP=61.82.23.9;Session=00000002;

User=bfernan;message=‘Error retrieving information from DB: NullPointerException’;

06:05:56 07.11.2011 INFO (Class1.java:100)
IP=192.168.2.99;Session=00000001;

User=bfernan;message=‘Finish method1’;

Multiple Connections Same User (II)


What about tabs?


Same Remote IP


Same Session ID

Multiple Connections Same User (II)


What about tabs?


Same Remote IP


Same Session ID




Log Transaction ID

Multiple Connections Same User (I)
-

Example

06:05:55 07.11.2011 INFO (Class1.java:41)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan;message=‘Start method1’;

06:05:55 07.11.2011 DEBUG (Class1.java:44)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan;message=‘
Before retrieve information from DB

;

06:05:55 07.11.2011 INFO (Class1.java:211)
IP=192.168.2.99;Session=00000001;
Transaction=00000002;
User=bfernan;message=‘Start method2’;

06:05:55 07.11.2011 DEBUG (Class1.java:220)
IP=192.168.2.99;Session=00000001;
Transaction=00000002;
User=bfernan;message=‘Before retrieve information from DB’;

06:05:55 07.11.2011 DEBUG (Class1.java:46)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan;message=‘
After retrieve information from DB

;

06:05:55 07.11.2011 INFO (Class1.java:50)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan;message=‘
Updating information

;

06:05:56 07.11.2011 DEBUG (Class1.java:94)
IP=192.168.2.99;Session=00000001;
Transaction=00000001
;User=bfernan;message=‘
Before save information in the DB

;

06:05:56 07.11.2011 DEBUG (Class1.java:96)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan;message=‘
After retrieve information in the DB

;

06:05:56 07.11.2011 ERROR (Class1.java:243)
IP=192.168.2.99;Session=00000001;
Transaction=00000002;
User=bfernan;message=‘Error retrieving information from DB:
NullPointerException’;

06:05:56 07.11.2011 INFO (Class1.java:100)
IP=192.168.2.99;Session=00000001;
Transaction=00000001;
User=bfernan
;message=‘
Finish method1

;

How to access the information?
v1.0


View the file


Human readable format


System utils (grep command)


$ grep '.*ERROR.* User bfernan .*' log_cra
-
ws.log


Easy for regext (Ex: key=value;)


$
grep ‘.*ERROR.*;User=bfernan;.*’ log_cra
-
ws.log

Cluster of Servers


Application distributed several Servers


1 log file for each server


Which one contains the error?

How to access the information?
v2.0


Forward log messages to a Server


Log4j Server



UI Tools


Apache Log4j Chainsaw


MindTree Insight

Analytic Tools


Splunk


Indexer


Search Engine


“Pseudo” real
-
time


Alerts



Example

Example

Example

What to log?


User requests (start & end)


Service methods calls (start & end)


Calls to external systems ( before & after)


Errors


Any relevant state

Conclusions (I)


Log everything useful, not only debug
information


Log to text files, human readable format


Use a template parseable with regexp (Ex:
key=value;)

Conclusions (II)


Use the appropriate level


One single action per line


Be careful with the performance


Be ready to profit of it

Why not logging standards?

“A good job can save a day of
work”

Спасибо!

Benedicto Fernandez

Software Engineer

CERN / GS
-
AIS