Java EE Servlet/JSP tutorial : Adding an error page, logging, and other forms of debugging
From Resin 4.0 Wiki
This cookbook in the Java EE Servlet tutorial covers setting up logging, debugging, and setting up a JSP error page. This tutorial is part of Java EE Tutorial covering JSP 2.2, and Servlets 3.0.
Contents
|
Logging
Background on logging
Logging was not added to Java until JDK 1.4. Java Logging relies on many ideas from the Log4j project, which has influenced many other frameworks for many other languages (like Python logging). Log4J brought this type of logging to the mainstream.
If it can be avoided, don't use other logging frameworks besides the ones that come with Java. The major reason is dependency management, harder to configure, and classloader issues. If you use three different frameworks and they depend on three different version of logging utilities, it is that much harder to find the right combination of versions of libraries and log utilities. When you are trying to debug a problem and you want to turn on logging, the last thing you want to do is figure out how to configure logging. You are trying to debug the problem not debug logging. Keeping your setup simple will help you.
Oracle has a tech note guide on logging, it is a little deep and not a very good getting started guide. There are many tutorials on logging (vogella logging tutorial Lars Vogel, OnJava Logging Tutorial, Jakob Jenkov's Logging Tutorial), but the Java tutorial does not have a logging trail. People still have issue with understanding Java logging.
One reason people still use non-standard logging is the formatting options with standard logging were sub par. In Java 7, they have been greatly improved. The SimpleFormatter is actually quite capable now. Resin, Open Source Java EE Application Server, has a built in Unified EL formater that can format standard log output in very flexible ways.
The key to logging is the ability to turn logging on and off. You don't want log messages being blasted to a log file in production. Production systems should not log that much unless you want to debug a specific areas. There are two ways to restrict what gets logged. Log categories and log levels.
Log Levels
The log levels define the importance of the log message.
The levels are as follows:
- SEVERE (highest importance, for errors)
- WARNING (possible errors or things that just should not happen)
- INFO (Information you always want in the output file)
- CONFIG (Configuration)
- FINE (Used for debugging)
- FINER (Used for finer grained debugging)
- FINEST (lowest importance for finest grained debugging, and tracing)
Then two more pseudo levels:
- OFF (turn everything off)
- ALL (turn everything on)
Resin and logging
Resin provides some additional support for logging. You can even turn logging on and off from the command line.
The following listing shows changing log levels in Resin:
~/workspace/javaee/Servers/Resin 4.0 at localhost-config/resin.xml
...
<!-- Logging configuration for the JDK logging API -->
<log-handler name="" level="all" path="stdout:"
timestamp="[%y-%m-%d %H:%M:%S.%s]"
format=" {${thread}} ${log.message}"/>
...
<!--
- level='info' for production
- 'fine' or 'finer' for development and troubleshooting
-->
<logger name="" level="${log_level?:'info'}"/>
<logger name="com.caucho.java" level="config"/>
<logger name="com.caucho.loader" level="config"/>
The expression ${log_level?:'info'} is used to set the global logger for the whole application server.
You can change this by setting the log_level property in the resin.properties.
Changing log levels in Resin.properties:
~/workspace/javaee/Servers/Resin 4.0 at localhost-config/resin.properties
# log_level : info # app-0.log_level : finest
The key idea is that properties in the properties file become properties that you can access in the resin.xml configuration file with Unified EL expressions.
Using Java log API
Using log class http://docs.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html
package com.bookstore;
...
import java.util.logging.Level;
import java.util.logging.Logger;
public class Book implements Cloneable {
private transient Logger log = Logger.getLogger(Book.class.getName());
...
public Book cloneMe() {
try {
return (Book) super.clone();
} catch (CloneNotSupportedException e) {
log.logp(Level.WARNING,
this.getClass().getName(),
"cloneMe", "Unable to clone", e);
return null;
}
}
...
Info about logp http://docs.oracle.com/javase/6/docs/api/java/util/logging/Logger.html#logp(java.util.logging.Level, java.lang.String, java.lang.String, java.lang.String, java.lang.Throwable)
Why you should not use static http://wiki.apache.org/commons/Logging/StaticLog
Another example:
package com.bookstore;
...
import java.util.logging.Logger;
import javax.enterprise.context.ApplicationScoped;
@ApplicationScoped @InMemory
public class BookRepositoryCollectionsImpl implements BookRepository {
...
private Book book(String title, String description, String aPrice,
String aPubDate) {
Date pubDate = null;
BigDecimal price = null;
try {
price = new BigDecimal(aPrice);
}catch (Exception ex) {
log.throwing(this.getClass().getName(), "book", ex);
}
try {
pubDate = dateFormat.parse(aPubDate);
}catch (Exception ex) {
log.throwing(this.getClass().getName(), "book", ex);
}
return new Book("" + (count++), title, description, price, pubDate);
}
Info about throwing http://docs.oracle.com/javase/6/docs/api/java/util/logging/Logger.html#throwing(java.lang.String, java.lang.String, java.lang.Throwable)
package com.bookstore;
...
import java.util.logging.Level;
import java.util.logging.Logger;
...
@ApplicationScoped @JDBC
public class BookRepositoryJDBCImpl implements BookRepository {
private transient Logger log = Logger.getLogger(Book.class.getName());
...
private <T> T withDB(JDBCRunner<T> runner) {
log.entering("BookRepositoryJDBCImpl", "withDB");
Connection connection = null;
try {
connection = dataSource.getConnection();
boolean auto = connection.getAutoCommit();
connection.setAutoCommit(false);
T result = runner.run(connection);
log.finest("about to commit");
connection.commit();
log.finest("committed");
connection.setAutoCommit(auto); //set it to what it was previously.
log.exiting("BookRepositoryJDBCImpl", "withDB");
return result;
}catch (Exception ex) {
log.log(Level.WARNING, "Transaction did not succeed", ex);
try {
log.finest("About to rollback transaction");
connection.rollback();
} catch (SQLException e) {
log.log(Level.WARNING, "Unable to rollback", ex);
}
throw new BookStoreException(ex);
} finally {
if (connection!=null) {
try {
connection.close();
} catch (Exception ex) {
log.log(Level.WARNING, "Unable to cleanup", ex);
}
}
}
}
}
http://docs.oracle.com/javase/6/docs/api/java/util/logging/Logger.html#exiting(java.lang.String, java.lang.String) http://docs.oracle.com/javase/6/docs/api/java/util/logging/Logger.html#entering(java.lang.String, java.lang.String, java.lang.Object[])
public class BookRepositoryJDBCImpl implements BookRepository {
private transient Logger log = Logger.getLogger(Book.class.getName());
...
@Override
public void updateBook(final String id, final String title, final String description,
final String price, final String pubDate) {
if (log.isLoggable(Level.FINER)) {
log.entering(this.getClass().getName(), "updateBook", new Object[]{id, title, description, price, pubDate});
}
withDB(new JDBCRunner<Book>(){
@Override
public Book run(Connection connection) throws Exception {
PreparedStatement prepareStatement = connection.prepareStatement("update book set title=?, " +
"description=?, price=?, pubdate=? where id = ?");
prepareStatement.setString(1, title);
prepareStatement.setString(2, description);
prepareStatement.setBigDecimal(3, new BigDecimal(price));
Calendar calendar = Calendar.getInstance();
calendar.setTime(dateFormat.parse(pubDate));
prepareStatement.setDate(4, new Date(calendar.getTimeInMillis()));
prepareStatement.setLong(5, Long.parseLong(id));
int rowCount = prepareStatement.executeUpdate();
if (rowCount!=1) {
throw new BookStoreException("Unable to update book into bookstore");
}
return null;
}});
if (log.isLoggable(Level.FINER)) {
log.exiting(this.getClass().getName(), "updateBook", new Object[]{id, title, description, price, pubDate});
}
}
Not so nice, too much duplicate names.
format="${log.level}, ${log.name}, ${log.shortName}, ${log.message}, ${log.sourceClassName}, ${log.sourceMethodName}, ${log.thrown}
[12-05-09 22:45:01.521], INFO, com.caucho.server.webapp.WebApp, WebApp, WebApp[production/webapp/admin.resin/ROOT] stopping, com.caucho.lifecycle.Lifecycle, toStopping, [12-05-09 22:37:56.811], FINER, com.bookstore.BookRepositoryJDBCImpl, BookRepositoryJDBCImpl, ENTRY, BookRepositoryJDBCImpl, withDB,
Log Levels and formatting
Better but still ugly
format="${log.level}, ${log.shortName}, ${log.message}, ${log.sourceClassName}, ${log.sourceMethodName}, ${log.thrown}"
[12-05-09 22:50:55.074]FINEST, BookRepositoryJDBCImpl, committed, com.bookstore.BookRepositoryJDBCImpl, withDB, , [12-05-09 22:50:55.074]FINER, BookRepositoryJDBCImpl, RETURN, BookRepositoryJDBCImpl, withDB, ,
Not so great for production but good for debugging and development
<log-handler name="" level="all" path="stdout:"
timestamp="[%y-%m-%d %H:%M:%S.%s]"
format="${fmt.sprintf('%-7s %-12s %-12s msg=%45s %s',log.level,log.shortName,log.sourceMethodName,log.message,log.thrown ? log.thrown : '')}"/>
[12-05-09 23:01:21.535]FINER BookRepositoryJDBCImpl withDB msg= ENTRY [12-05-09 23:01:21.681]FINEST BookRepositoryJDBCImpl withDB msg= about to commit [12-05-09 23:01:21.681]FINEST BookRepositoryJDBCImpl withDB msg= committed [12-05-09 23:01:21.681]FINER BookRepositoryJDBCImpl withDB msg= RETURN [12-05-09 23:01:23.550]FINER BookRepositoryJDBCImpl withDB msg= ENTRY [12-05-09 23:01:23.560]FINEST BookRepositoryJDBCImpl withDB msg= about to commit [12-05-09 23:01:23.561]FINEST BookRepositoryJDBCImpl withDB msg= committed [12-05-09 23:01:23.561]FINER BookRepositoryJDBCImpl withDB msg= RETURN [12-05-09 23:01:26.750]FINER BookRepositoryJDBCImpl updateBook msg= ENTRY 6 Vampire Diaries 22 05/05/1945 [12-05-09 23:01:26.751]FINER BookRepositoryJDBCImpl withDB msg= ENTRY [12-05-09 23:01:26.754]FINEST BookRepositoryJDBCImpl withDB msg= about to commit [12-05-09 23:01:26.755]FINEST BookRepositoryJDBCImpl withDB msg= committed [12-05-09 23:01:26.755]FINER BookRepositoryJDBCImpl withDB msg= RETURN [12-05-09 23:01:26.755]FINER BookRepositoryJDBCImpl updateBook msg= RETURN [Ljava.lang.Object;@549b6976
Logging methods for important classes without tons of boiler plate code
problem too much boiler plate code
@Override
public void updateBook(final String id, final String title, final String description,
final String price, final String pubDate) {
if (log.isLoggable(Level.FINER)) {
log.entering(this.getClass().getName(), "updateBook", new Object[]{id, title, description, price, pubDate});
}
//do stuff
if (log.isLoggable(Level.FINER)) {
log.exiting(this.getClass().getName(), "updateBook", new Object[]{id, title, description, price, pubDate});
}
}
A lot of code.... too much for basic trace logging.
background http://java.dzone.com/articles/cdi-aop
package com.bookstore;
import java.lang.annotation.Retention;
import java.lang.annotation.Target;
import static java.lang.annotation.ElementType.*;
import static java.lang.annotation.RetentionPolicy.*;
import javax.interceptor.InterceptorBinding;
@InterceptorBinding
@Retention(RUNTIME) @Target({TYPE, METHOD})
public @interface Debuggable {
}
package com.bookstore;
...
@ApplicationScoped @JDBC @Debuggable
public class BookRepositoryJDBCImpl implements BookRepository {
...
package com.bookstore;
import java.util.logging.Level;
import java.util.logging.Logger;
import javax.interceptor.AroundInvoke;
import javax.interceptor.Interceptor;
import javax.interceptor.InvocationContext;
@Debuggable @Interceptor
public class LoggingAdvice {
@AroundInvoke
public Object checkSecurity(InvocationContext joinPoint) throws Exception {
String methodName = joinPoint.getMethod().getName();
String className = joinPoint.getTarget().getClass().getName();
Object[] parameters = joinPoint.getParameters();
/*Find logger*/
Logger log = Logger.getLogger(className);
/* Only debug if not FINEST */
if (!log.isLoggable(Level.FINEST)) {
return joinPoint.proceed();
}
log.entering(className, methodName, parameters);
Object returnObject = joinPoint.proceed();
log.exiting(className, methodName, parameters);
return returnObject;
}
}
<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://java.sun.com/xml/ns/javaee"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/beans_1_0.xsd">
<interceptors>
<class>com.bookstore.LoggingAdvice</class>
</interceptors>
</beans>
