Monday, March 30, 2009

AspectJ Development Tools - Inline aspect visualization inside Eclipse

As I wrote about using AspectJ for serviceability instrumentation, I thought I would also spend some time publishing a couple of screenshots of a great addition to your Eclipse environment.

It is called AspectJ Development Tools, or AJDT, for short. AJDT adds a perspective and a handful of views that make it easy to visualize how the aspects are cross-cutting your code base.

Installation

Your first step is to visit the AJDT web site, go to the "Downloads" page and determine the right level of AJDT for your Eclipse environment. For those using any of the Rational Software Development v7.0 siblings, such as Rational Software Architect, you are looking into the 3.2 version.

The installation of the plugin follows the standard Eclipse "Help->Software Updates->Find and Install..." sequence, where you will be able to register the Eclipse update side for AJDT.

Converting a Java project into an AspectJ project

You will need to convert Java projects into AspectJ projects before you can use Eclipse to apply aspects to your Java code. The "conversion" is fairly benign and reversible, adding a couple of facets to the ".project" file.

An "AspectJ" sub-menu will be displayed whenever you right-click any Java project, with a single and unmistakable option named "Convert to AspectJ Project". After the conversion, other options become available, including the action to undo the conversion.

Aspect visualization embedded into Java code

The AJDT extensions will show markers to the left of Java source code,with the icons indicating the type of join point, such as "around", "before" and "after". Note that you can also display the "Cross References" view of the advices being applied to a particular point in the code.


Click on the thumbnail to see a larger image

Simultaneous Aspect visualization for multiple files

Using the Aspect Visualization perspective, you can have a broader view into how the aspects are crosscutting your projects.
Note how the screen is logically divided in three parts, with the package selection on the left, a graphical representation of the advices for each class in the middle section, and a selector for the aspects you want to browse.

What I like the best is that all screen elements are fully navigable, with double-clicks to the classes or advices in the graphical display taking you to their respective location in the Java source code.


Click on the thumbnail to see a larger image

Monday, March 16, 2009

AspectJ for Java logging: Serviceability without the clutter ("around" we go) - part 3

Whenever I reuse someone else's code at the source level, I often discover that it uses some different logging toolkit than what I am using.
Log4J seems to take the prize because a lot of developers used it before JSR-47 came out, and some **still** use Log4J in defiance of JSR-47's release.
JRAS, from older versions of WebSphere, also comes to mind.

At any rate, combining two different log toolkits produces some undesirable results, mostly (1) two different configuration steps and (2) two different file outputs. You can add a new handler to Log4J to redirect its calls to solve problem "2", but "1" is still there rearing its ugly head.

AspectJ allows one to replace calls to a given method with different calls. You got it, how about an Aspect that replaces all Log4J calls with JSR-47 calls?

The alternative? Ripping through every single method in the second code-base to replace Log4J calls with JSR-47 calls, but it is very likely that the original code owner will not support your forked code-base. Yes, I don't like it either, and that is why I wrote this other aspect for a recent project.

There are ways of applying this technique to an existing JAR file if you are reusing libraries instead of source code. Theme for the next posting.

----
package my.project;

import java.util.logging.Level;
import java.util.logging.Logger;

/**
* Aspect used to wrap Log4J to ensure consistent logging throughout the entire project.
*
* @author Denilson Nastacio
*/
public aspect Log4J {

private static final Logger trace = Logger.getLogger("trace.my.project");

/*
* Pointcuts
*/

/**
* Pointcut for all log4j calls within the target module
*/
pointcut log4jCalls():
target(org.apache.commons.logging.Log) &&
within(my.someone.else.code*.*);

/**
* Pointcuts for isInfoEnabled calls.
*/
pointcut log4jIsInfoEnabled():
log4jCalls() &&
call(boolean isInfoEnabled());

/**
* Pointcuts for isTraceEnabled calls.
*/
pointcut log4jIsTraceEnabled():
log4jCalls() &&
call(boolean isTraceEnabled());

/**
* Pointcuts for isDebugEnabled calls.
*/
pointcut log4jIsDebugEnabled():
log4jCalls() &&
call(boolean isDebugEnabled());

/**
* Pointcuts for isWarnEnabled calls.
*/
pointcut log4jIsWarnEnabled():
log4jCalls() &&
call(boolean isWarnEnabled());

/**
* Pointcuts for isErrorEnabled calls.
*/
pointcut log4jIsErrorEnabled():
log4jCalls() &&
call(boolean isErrorEnabled());

/**
* Pointcuts for isFatalEnabled calls.
*/
pointcut log4jIsFatalEnabled():
log4jCalls() &&
call(boolean isFatalEnabled());

/**
* Pointcuts for info calls.
*/
pointcut log4jInfo(Object o):
log4jCalls() &&
args(o) &&
call(void info(Object));
pointcut log4jInfoEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void info(Object,Throwable));

/**
* Pointcuts for trace calls.
*/
pointcut log4jTrace(Object o):
log4jCalls() &&
args(o) &&
call(void trace(Object));
pointcut log4jTraceEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void trace(Object,Throwable));

/**
* Pointcuts for debug calls.
*/
pointcut log4jDebug(Object o):
log4jCalls() &&
args(o) &&
call(void debug(Object));
pointcut log4jDebugEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void debug(Object,Throwable));

/**
* Pointcuts for warn calls.
*/
pointcut log4jWarn(Object o):
log4jCalls() &&
args(o) &&
call(void warn(Object));
pointcut log4jWarnEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void warn(Object,Throwable));

/**
* Pointcuts for error calls.
*/
pointcut log4jError(Object o):
log4jCalls() &&
args(o) &&
call(void error(Object));
pointcut log4jErrorEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void error(Object,Throwable));

/**
* Pointcuts for fatal calls.
*/
pointcut log4jFatal(Object o):
log4jCalls() &&
args(o) &&
call(void fatal(Object));
pointcut log4jFatalEx(Object o, Throwable ex):
log4jCalls() &&
args(o,ex) &&
call(void fatal(Object,Throwable));

/*
* Join points
*/

/**
* Replace calls to Log.isInfoEnabled
*/
boolean around(): log4jIsInfoEnabled() {
if (trace.isLoggable(Level.INFO)) {
return true;
} else {
return false;
}
}

/**
* Replace calls to Log.isTraceEnabled
*/
boolean around(): log4jIsTraceEnabled() {
if (trace.isLoggable(Level.FINER)) {
return true;
} else {
return false;
}
}

/**
* Replace calls to Log.isDebugEnabled
*/
boolean around(): log4jIsDebugEnabled() {
if (trace.isLoggable(Level.FINEST)) {
return true;
} else {
return false;
}
}

/**
* Replace calls to Log.isWarnEnabled
*/
boolean around(): log4jIsWarnEnabled() {
if (trace.isLoggable(Level.WARNING)) {
return true;
} else {
return false;
}
}

/**
* Replace calls to Log.isErrorEnabled
*/
boolean around(): log4jIsErrorEnabled() || log4jIsFatalEnabled() {
if (trace.isLoggable(Level.SEVERE)) {
return true;
} else {
return false;
}
}

/**
* Replace calls to Log.info
*/
void around(Object o): log4jInfo(o) {
if ("".equals(o) == false) {
trace.logp(Level.INFO,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString());
}
}
void around(Object o, Throwable ex): log4jInfoEx(o, ex) {
trace.logp(Level.INFO,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString(), ex);
}

/**
* Replace calls to Log.trace
*/
void around(Object o): log4jTrace(o) {
trace.logp(Level.FINER,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString());
}
void around(Object o, Throwable ex): log4jTraceEx(o, ex) {
trace.logp(Level.FINER,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString(), ex);
}

/**
* Replace calls to Log.debug
*/
void around(Object o): log4jDebug(o) {
trace.logp(Level.FINEST,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString());
}
void around(Object o, Throwable ex): log4jDebugEx(o, ex) {
trace.logp(Level.FINEST,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString(), ex);
}

/**
* Replace calls to Log.warn
*/
void around(Object o): log4jWarn(o) {
trace.logp(Level.WARNING,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString());
}
void around(Object o, Throwable ex): log4jWarnEx(o, ex) {
trace.logp(Level.WARNING,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString(), ex);
}

/**
* Replace calls to Log.error and Log.fatal
*/
void around(Object o): log4jError(o) ||
log4jFatal (o) {
trace.logp(Level.SEVERE,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString());
}
void around(Object o, Throwable ex): log4jErrorEx(o, ex) ||
log4jFatalEx(o,ex) {
trace.logp(Level.SEVERE,
thisJoinPointStaticPart.getSourceLocation().getWithinType().getName(),
thisJoinPointStaticPart.getSourceLocation().toString(),
o.toString(), ex);
}

}

Friday, March 13, 2009

AspectJ for Java logging: Serviceability without the clutter - part 2


In the previous entry about an Aspect for Java logging, I forgot to add a higher-level picture of the end-results.

Let's say your Java project has 4 major packages:
  1. my.otherproject.A
  2. my.project.B
  3. my.project.B.parsers
  4. my.project.C

With the Java logging aspect added to the code base, you can invoke your program with the standard Java logging option:
java -Djava.util.logging.config.file=<logging.properties> application.class

where <logging.properties> is a standard Java logging configuration file.

You can read more about the structure of this file in the Java Logging Overview, but here is an example of what I use:

# "handlers" specifies a comma separated list of log Handler 
# classes. These handlers will be installed during VM startup.
# Note that these classes must be on the system classpath.
# By default we only configure a ConsoleHandler, which will only
# show messages at the INFO and above levels.
handlers = java.util.logging.ConsoleHandler

# To also add the FileHandler, use the following line instead.
#handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# Default global logging level.
# This specifies which kinds of events are logged across all loggers.
# For any given facility this global level
can be overriden by a facility
# specific level
.
# Note that the ConsoleHandler also has a separate level

# setting to limit messages printed to the console.
trace.my.level = INFO
trace.my.project.level = FINER

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = project%u.%g.log
java.util.logging.FileHandler.limit = 5000000
java.util.logging.FileHandler.count = 5
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.level = FINEST
java.util.logging.FileHandler.append = false

# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter


-----





Since the Java logging handles are hierarchical, the declaration of "trace.my.level = INFO" sets the default to all packages, whereas the declaration "trace.my.project.level = FINER" entry sets a different tracing level for your instrumented classes under the "my.project" Java package.





Dealing with verbose classes





One can tweak the "method" join point to exclude verbose classes from the tracing aspect, along the lines of:





    pointcut method():


        execution(* my.project..*.*(..)) &&


        !within(my.project.D.*) &&


        !within(Logging) &&


        !within(excluded.class.1) &&


        !within(excluded.class.2) &&


        !within(excluded.class.n);


 





Dealing with methods inside loops






This point is a bit more complicated and I'll get to it in a different post.

Tuesday, March 10, 2009

Dealing with timestamps in BIRT reports

While trying to match date/time fields between a BIRT (Business Intelligence and Reporting Tools) report design file and a web service, I did not stumble upon any good tips on the BIRT Eclipse website, but eventually found this entry on the BIRT Exchange website: Convert String Date to Date Object in BIRT.

The example was not a perfect match for what I needed but threw me close enough to the solution.

The web service returns a long value corresponding to the time using the Java/C convention for milliseconds since Jan/1/1970 0:00:00 GMT”. Inside the BIRT data-set though, I could not find the “Timestamp” field available for other kinds of data-sources, such as the XML data-source. Returning a string representing the date and time is never a good strategy since it discards the time zone information.

The solution was to create a computed field with “Date Time” type, then use this expression derived from the article to convert the milliseconds value retrieved from the web service (originally named “Date”):

df = new Packages.java.util.Date();
df.setTime(row["Date"]);
df



image



image



The next step was to indicate the correct type for the new computed parameter “DateTime” in my chart:



image

Tuesday, March 3, 2009

AspectJ for Java logging: Serviceability without the clutter - part 1

I have grown fond of AspectJ in the past years, probably at the same rate I have grown tired of writing or referencing the same cross-cutting snippets of code all over the code-base of a project.

In the way of background, AspectJ is a Java extension for "Aspect Oriented Programming" (PDF download), or AOP for short.

You can read the entire background in the previous link, but in a nutshell, AOP allows you to abstract common code snippets (advices, in AspectJ lingo) that are executed on common points of the code-base (join points.)

As a concrete example, I'll reference an Aspect that I have been perfecting on my last three projects: adding debugging trace statements to the entry/exit of all methods in a project.

I won't lie to you, it is not a trivial technique and the average Java programmer who eventually inherits your code base will hate your guts.

Setup your environment

Using the Eclipse environment and the AJDT (AspectJ Development Tools) is almost mandatory when dealing with aspects in Java. If you already have one of the Rational Software Development Platform siblings installed on your machine, such as Rational Software Architect, you are in good shape too, just pay attention to their underlying Eclipse version in order to select the right level of AJDT.

Since this is not an Eclipse primer, I assume you know how to deal with installation of plugins from update sites.

Trace statements

If you want somewhat decent traceability, you should look into three types of statements:

Method entry:

    if (trace.isLoggable(Level.FINER)) {
        trace.entering(<CLASS_NAME>, <METHOD_NAME>, <args> ) ;
    }


Method exit:

    if (trace.isLoggable(Level.FINER)) {
        trace.exiting(<CLASS_NAME>, <METHOD_NAME>, <args> ) ;
    }


Exception handling:

    catch (<EXCEPTION_CLASS> e) {
        trace.logp(Level.SEVERE,
<CLASS_NAME>, <METHOD_NAME>,
                   "Caught exception: " + e.getClass().toString(),
                   e);
    }


The Logging aspect

This is also not a primer on AspectJ, so that I assume you know that aspects go inside an "Aspect" file sitting inside any regular folder corresponding to a Java package. Here is what I have for trace.


package my.project.aspects;

import java.util.logging.Level;
import java.util.logging.Logger;

/**
* Aspect for Java logging throughout the code base.
*/
public aspect Logging {

    private static Logger trace = Logger.getLogger("trace.my.project");

   /*
     * Pointcuts
     */
   
 
    /**
     * Execution body for all methods.
     */
    pointcut method():
        execution(* my.project..*.*(..)) &&
        !within(my.project.D.*) &&
        !within(Logging);

    /**
     * Exception handling blocks inside all methods.
     */
    pointcut methodError(Throwable t):
args(t) &&
        handler(Throwable+) &&
        within(my.project..*.*) &&
        !within(my.project.D.*) &&
        !within(Logging);

    /*
     * Join points
     */

    /**
     * Entry trace statements for all methods.
     */
    before(): method() {
        if (trace.isLoggable(Level.FINER)) {
            trace.entering(
thisJoinPointStaticPart.getSignature().getDeclaringTypeName(),

                    thisJoinPointStaticPart.getSignature().toString(),
                    thisJoinPoint.getArgs());
        }
    }

    /**
     * Exit trace statements for all methods.
     */
    after() returning (Object result): method() {
        if (trace.isLoggable(Level.FINER)) {
            trace.exiting(
thisJoinPointStaticPart
.getSignature().getDeclaringTypeName(),
                    thisJoinPointStaticPart.getSignature().toString(),
                    result);
        }
    }

    /**
     * Exception handling blocks inside all methods.
     */
    before(Throwable t): methodError(t) {
        if (trace.isLoggable(Level.SEVERE)) {
            trace.logp(Level.SEVERE,
thisJoinPointStaticPart.getSignature().getDeclaringTypeName(),
                    thisJoinPointStaticPart.getSignature().toLongString(),
                    "Caught exception: " + t.getClass().toString(),
t);
        }
    }
 
}







Advanced reading





In the way of advanced reading, one can browse through developerWorks excellent AOP@Work series.





I particularly like "Next Steps with Aspects" and "AOP Myths and Realities".