Why Logging?

Transcrição

Why Logging?

Software Construction
Documentation and Logging
Jürg Luthiger
University of Applied Sciences Northwestern Switzerland
Institute for Mobile and Distributed Systems
Learning Target
You
can use Mock Objects as an efficient alternative
for Unit Testing
know how to setup log4j
can use log4j
Institut für Mobile und Verteilte Systeme
J. Luthiger
2
Documentation
IMPORTANT

All documentation is a mirror of the code
Build Documentation In, Don't Bolt It On
Tip 68 (The Pragmatic Programmer)
J. Luthiger
3
Internal Documentation
Includes source code, comments, design and
test documents, …
Documenting the source code
Use Naming Convention
Integrate comments into source code
Use tool to generate appropriate docs out of the
source code
Try to keep source and code in sync!

J. Luthiger
4
Java Naming Conventions
Naming conventions make programs more
understandable by making them
easier to read
easier to understand
easier to improve
easier to detect bugs

Use coding guidelines

e.g. from SUN "Code Conventions for the JavaTM
Programming Language" (see Resources)
J. Luthiger
5
Tool JavaDoc
Purpose

Instead of writing and maintaining separate
documentation, the programmer writes speciallyformatted comments in the Java code itself. JavaDoc
takes these comments and transforms them into
documentation in HTML (web page) format.
J. Luthiger
6
General Format
Start with the normal beginning of comment
delimiter (/*) followed by another (*). All
following lines start with an asterisk lined up
under the first asterisk in the first line. The last
line contains just the normal end of comment
delimiter (*/).
/**
* The number of students in the class.
* This variable must not be negative or greater than 200.
*/
public int numStudents;
J. Luthiger
7
JavaDoc Tags
Tags for Classes

@author
Tags for Methods
@param
@return
@exception

Tags for Variables

needs no tags, just normal JavaDoc comment
J. Luthiger
8
Package Level Comments
Each package can have its own package-level
doc comment source file
The Javadoc tool will merge them into the final
documentation
This file is named package.html
This file is kept in the source directory
J. Luthiger
9
Integrate JavaDoc into the Build Process
Use the javadoc Ant Task

Core Task (see Ant's Website)
J. Luthiger
10
External Documentation
Includes everything which is published to the
outside world like user manual, …
Use a markup language to produce the final
documentation

e.g. DocBook, Latex, …
DocBook
XML based
text-oriented => easily to integrate into a VCS
supports different output formats:

z

HTML, PDF, Tex, …
supports automation => Ant integration
J. Luthiger
11
Resources
Sun Reference:
"How to Write Doc Comments for the Javadoc Tool"
http://java.sun.com/j2se/javadoc/writingdoccomments
Code Conventions for the Java Language
http://java.sun.com/docs/codeconv/html/CodeConvTOC.doc.html
DocBook Home
http://www.docbook.org
J. Luthiger
12
Why Logging?
Debuggers focus on the state of a program NOW

A stack trace can you tell only how got here directly
It is not possible to detect what was before this actual call
Logging can provide information about the state of a
program or a data structure over time

Logging can reveal several classes of errors that debugger's
can't
Logging is invaluable in any system where time itself is a
factor

concurrent processes
real-time systems
event-based application
distributed environment
J. Luthiger
13
Brian W. Kernighan says...
As personal choice, we tend not to use debuggers beyond getting a
stack trace or the value of a variable or two. One reason is that it is
easy to get lost in details of complicated data structures and control
flow; we find stepping through a program less productive than thinking
harder and adding output statements and self-checking code at critical
places. Clicking over statements takes longer than scanning the output
of judiciously-placed displays. It takes less time to decide where to put
print statements than to single-step to the critical section of code, even
assuming we know where that is. More important, debugging
statements stay with the program; debugging sessions are transient.
In "The Practice of Programming"
J. Luthiger
14
Approaches to Logging
System.out.println
Poor performance
All or none – Example below
Some people use a class like:

Class foo{
public static final boolean debug = true;
public void test(){
if (debug) System.out.println(“I exist only in a test environmnet”);
}
}
Custom log api

More code to maintain
Classic build vs. buy (or use) decision
Open Source (like Log4j)
J. Luthiger
15
Java Specification Request JSR 47
Enable/disable logging at runtime
Control logging at a fairly fine granularity

Disable logging for specific functionality
Bridge services that connect the logging APIs to existing
logging services (Operating System Logs, Third party
logs)
J. Luthiger
16
Requirements for a Logging Framework
Configuration of the logging features should be
externalized
Log messages should have priorities
Logging should support different message
formats
Logging should not slow down the program
speed, it must support message caching
J. Luthiger
17
Logging Frameworks
Log4j:
Apache Open Source Project
http://jakarta.apache.org/log4j
Java1.4 Logging
Logging API by SUN
introduced with JDK1.4
http://java.sun.com/j2se/1.4.1/docs/guide/util/logging/
J. Luthiger
18
log4j background
Originally developed by IBM at their Zurich
research lab. (www.zurich.ibm.com)
Currently maintained by Source Forge
Open source
Release 1.0+ documentation at
http://logging.apache.org/log4j/docs/
J. Luthiger
19
Basic API
As of 1.0, printing messages are of the form:
debug(Object message, Throwable t)
debug(Object message)
If the 1st argument is a String object, it will be written in its present
form. Other objects rendered by a registered Object Renderer for its
class or using the Object.toString method.
J. Luthiger
20
Basic Usage Example
Standard usage:
class Foo {
Logger logger = null;
public Foo(){
logger = Logger.getLogger(Foo.class);
logger.info(“Constructing foo”);
}
public String doStuff(Long x){
logger.debug(“doing stuff”);
}
}
J. Luthiger
21
Priorities
Five recognized message priorities:
DEBUG,INFO,WARN,ERROR ,FATAL
Priority specific log methods following the the form:
debug(Object message);
debug(Object message, Throwable throwable);

General log methods for wrappers and custom priorities:

log(Priority level, Object message);
log(Priority level, Object message,Throwable throwable);
Localized log methods supporting ResourceBundles:

L7dlog(Priority level, String message, Throwable throwable)
L7dlog(Priority level, Object[] params, Throwable throwable)
setResourceBundle(ResourceBundle);
J. Luthiger
22
Priorities Usage
DEBUG

Least Importance Level
Log requests that are relevant while debugging the application.
INFO

Log requests that informs the user of the application about
something (e.g., informs him about application progress)
WARN

Log requests to alert about harmful situations.
ERROR

When an error is encountered (but you application can still run).
FATAL

In case of very sever errors after which your application cannot
continue any more.
J. Luthiger
23
Loggers
The notion of loggers lies at the heart of log4j.
Loggers define a hierarchy and give the programmer run-time
control on which statements are printed or not.
Loggers are assigned priorities. A log statement is printed
depending on its priority and its category.
Used to support output to multiple logs (Appenders) at the same
time.
logger = Logger.getLogger(User.class);
J. Luthiger
24
Logger Names
Name loggers by locality.

It turns out that instantiating a logger in each class, with the
logger name equal to the fully-qualified name of the class, is a
useful and straightforward approach of defining loggers.
However, this is not the only way for naming loggers. A
common alternative is to name loggers by functional
areas. For example, the "database" category, "RMI"
category, "security" category, or the "XML" category.
J. Luthiger
25
Benefits of using fully qualified class names
It is very simple to implement.
It is very simple to explain to new developers.
It automatically mirrors the application's own
modular design.
It can be further refined at will.
Printing the logger automatically gives
information on the locality of the log statement.
J. Luthiger
26
Root Logger
If no logger is defined via a configuration file or
programmatically, then all messages will be sent to the
root logger.
All loggers define

a priority level
an appender
# set log level of rental package to DEBUG
log4j.logger.ch.fhnw.edu.rental=DEBUG
# configuration of stdout appender
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
J. Luthiger
27
Appenders
An Appender is a object that sends log messages to their final
destination.

ConsoleAppender - Write log to System.out or System.err
FileAppender – Write to a log file
SocketAppender – Dumps log output to a socket
SyslogAppender – Write to the syslog.
NTEventLogAppender – Write the logs to the NT Event Log system.
RollingFileAppender – After a certain size is reached it will rename the
old file and start with a new one.
SocketAppender – Dumps log output to a socket
SMTPAppender – Send Messages to email
JMSAppender – Sends messages using Java Messaging Service
…
… or create your own!
J. Luthiger
28
PatternLayout – Customize your message
Used to customize the layout of a log entry. The format is closely related to

conversion pattern of the printf function in ‘c’
see
http://logging.apache.org/log4j/docs/api/org/apache/log4j/PatternLayout.html
The following options are available:

c - Used to output the Logger name of the logging event.
C - Used to output the fully qualified class name of the caller issuing the logging
request.
d - Used to output the date of the logging event.
The date conversion specifier may be followed by a date format specifier
enclosed between braces.
For example: %d{HH:mm:ss,SSS} or %d{dd MMM yyyy HH:mm:ss,SSS}.
If no date format specifier is given then ISO8601 format is assumed
F - Used to output the file name where the logging request was issued.
l - Used to output location information of the caller which generated the logging
event. (C+M+L)
L - Used to output the line number from where the logging request was issued.
Performance penalty!
J. Luthiger
29
PatternLayout – Customize your message

n - Outputs the platform dependent line separator character or characters.
M - Used to output the method name where the logging request was issued.
p - Used to output the priority of the logging event.
t - Used to output the name of the thread that generated the logging event.
x - Used to output the NDC (nested diagnostic context) associated with the
thread that generated the logging event.
J. Luthiger
30
Sample log4j.xml
log4j.xml will be searched first
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
<appender name="stdout" class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.SimpleLayout"></layout>
</appender>
<root>
<priority value="debug"></priority>
<appender-ref ref="stdout"/>
</root>
</log4j:configuration>
J. Luthiger
31
Sample log4j.properties
log4j.rootLogger=info, stdout
# set log level of rental package to DEBUG
log4j.logger.ch.fhnw.edu.rental=debug
# configuration of stdout appender
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.SimpleLayout
J. Luthiger
32
Logging performance
Log4j claims to be fast and flexible:
speed first
flexibility second

Although log4j has a many features, its first
design goal was speed.

Some log4j components have been rewritten many
times to improve performance.
J. Luthiger
33
Cost of logging
When logging is turned off entirely or just for a set of
priorities, the cost of a log request consists of a method
invocation plus an integer comparison.
The typical cost of actually logging is about 100 to 300
microseconds. This is the cost of formatting the log
output and sending it to its target destination.
logger.debug("Entry number: " + i + " is " +
String.valueOf(entry[i]));
Example:
constructing the message parameter, i.e. converting both integer i and
entry[i] to a String, and concatenating intermediate strings, regardless of
whether the message will be logged or not
J. Luthiger
34
Hidden costs of logging
Method invocation involves the "hidden" cost of
parameter construction.
To avoid the parameter construction cost write:
if (logger.isDebugEnabled() {
logger.debug("Entry number: " + i + " is " +
String.valueOf(entry[i]));
}
J. Luthiger
35
Some best practices
Don't use e.printStackTrace()
use log.error("Exception message", e)
instead
Don't log exception and throw it again
Don't swallow the Stack Trace
} catch(SQLException e){
throw new RuntimeException("DB excpetion"+e.getMessage());
}
J. Luthiger
36
Apache Commons Logging JCL
The Logging package is an ultra-thin bridge
between different logging implementations.
Commons Logging will guess (discover) the
preferred logging system and you won't need to
do any configuration of JCL at all!
There are two base abstractions used by JCL:
Log (the basic logger)
LogFactory (which knows how to create Log
instances).

J. Luthiger
37
Using JCL
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
...
private Log log = LogFactory.getLog(this.getClass());
...
if (log.isDebugEnabled()) {
log.debug("Song '" + song.getTitle() + "' added to playlist");
}
J. Luthiger
38