Loggin Best Practices

Transcript Loggin Best Practices

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
06:05:56
Integer
06:05:56
06:05:56
07.11.2011 INFO (Class1.java:211) Start method2
07.11.2011 INFO (Class1.java:211) Parameter ‘age’ is not an
07.11.2011 INFO (Class1.java:211) Finish method2
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
06:05:56 07.11.2011
Integer
06:05:56 07.11.2011
06:05:56 07.11.2011
06:05:56 07.11.2011
information from DB
INFO (Class1.java:211) Start method2
INFO (Class1.java:211) Parameter ‘age’ is not an
INFO (Class1.java:211) Finish method2
INFO (Class1.java:211) Start method2
DEBUG (Class1.java:220) Before retrieve
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)
message=‘Start method1’;
06:05:55 07.11.2011
from DB’;
06:05:55 07.11.2011
from DB’;
06:05:55 07.11.2011
06:05:55 07.11.2011
the DB’;
06:05:56 07.11.2011
the DB’;
User=bfernan;
DEBUG (Class1.java:44) message=‘Before retrieve information
DEBUG (Class1.java:46) message=‘After retrieve information
INFO (Class1.java:50) message=‘Updating information’;
DEBUG (Class1.java:94) message=‘Before save information in
DEBUG (Class1.java:96) message=‘After save information in
06:05:56 07.11.2011 INFO (Class1.java:100)
message=‘Finish method1’;
User=bfernan;
06:05:56 07.11.2011 INFO (Class1.java:211)
message=‘Start method2’;
User=xxxxxxx;
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
user1
Log Session ID
Log Remote IP
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